Pepper: Move NaCl fatal logging to Chrome IPC.

Pepper: Move NaCl fatal logging to Chrome IPC.

nacl_helper reports the last few log messages to the renderer when a LOG_FATAL
message is logged in the plugin. This currently uses the "bootstrap" channel,
which we would like to get rid of.

This change registers a callback in the loader process to log fatal messages to
the JS console as soon as they're reported.

I had to add some synchronization to "flush" the task queue for the IPC task
runner in this change. That's because ChannelProxy::Send queues the send job
on a background thread. Unfortunately, the plugin could exit before that send
happens, preventing messages from being logged to the JS console.

I tested this manually by forcing a plugin crash after StartModule() in
service_runtime.cc.

BUG=391039

[dmichael (off chromium), 2014-07-30 20:18:52]

https://codereview.chromium.org/424893003/diff/80001/components/nacl/loader/n...
File components/nacl/loader/nacl_listener.cc (right):

https://codereview.chromium.org/424893003/diff/80001/components/nacl/loader/n...
components/nacl/loader/nacl_listener.cc:126:
base::TimeDelta::FromMilliseconds(50));
I think I'd rather see a SendFatalLog method on NaClTrustedListener, with
FlushIpcTaskRunner private. Just to avoid any future users of
NaClTrustedListener thinking they should do this Flush if they send a message.

https://codereview.chromium.org/424893003/diff/80001/components/nacl/loader/n...
File components/nacl/loader/nacl_trusted_listener.cc (right):

https://codereview.chromium.org/424893003/diff/80001/components/nacl/loader/n...
components/nacl/loader/nacl_trusted_listener.cc:51: waitable_event_.Reset();
Note, if there's ever a second caller to this method, it might not work right...
caller A calls FlushIpcTaskRunner
caller B calls FlushIpcTaskRunner
A's task runs and signals waitable_event_; both are woken up, even though B's
thing didn't actually happen yet.

...more reason maybe to bury it behind a SendLogFatal kind of method instead.
You might even consider making it DCHECK that it's only called once, and you
wouldn't need to bother with Reset().

[teravest, 2014-07-30 20:44:12]

On Wed, Jul 30, 2014 at 2:18 PM,  <dmichael@chromium.org> wrote:
>
>
https://codereview.chromium.org/424893003/diff/80001/components/nacl/loader/n...
> File components/nacl/loader/nacl_listener.cc (right):
>
>
https://codereview.chromium.org/424893003/diff/80001/components/nacl/loader/n...
> components/nacl/loader/nacl_listener.cc:126:
> base::TimeDelta::FromMilliseconds(50));
> I think I'd rather see a SendFatalLog method on NaClTrustedListener,
> with FlushIpcTaskRunner private. Just to avoid any future users of
> NaClTrustedListener thinking they should do this Flush if they send a
> message.

I feel gross having two separate Send() routines, but it's less work
than fixing up FlushIpcTaskRunner for multiple concurrent users.

>
>
https://codereview.chromium.org/424893003/diff/80001/components/nacl/loader/n...
> File components/nacl/loader/nacl_trusted_listener.cc (right):
>
>
https://codereview.chromium.org/424893003/diff/80001/components/nacl/loader/n...
> components/nacl/loader/nacl_trusted_listener.cc:51:
> waitable_event_.Reset();
> Note, if there's ever a second caller to this method, it might not work
> right...
> caller A calls FlushIpcTaskRunner
> caller B calls FlushIpcTaskRunner
> A's task runs and signals waitable_event_; both are woken up, even
> though B's thing didn't actually happen yet.
>
> ...more reason maybe to bury it behind a SendLogFatal kind of method
> instead. You might even consider making it DCHECK that it's only called
> once, and you wouldn't need to bother with Reset().

It won't work right for multiple concurrent callers, but I had left
this simple since I only had one user, and didn't want to get fancy
with managing the memory for a queue of WaitableEvents.

>
> https://codereview.chromium.org/424893003/

To unsubscribe from this group and stop receiving emails from it, send an email
to chromium-reviews+unsubscribe@chromium.org.

[dmichael (off chromium), 2014-07-30 21:17:48]

lgtm

https://codereview.chromium.org/424893003/diff/140001/components/nacl/loader/...
File components/nacl/loader/nacl_trusted_listener.cc (right):

https://codereview.chromium.org/424893003/diff/140001/components/nacl/loader/...
components/nacl/loader/nacl_trusted_listener.cc:63: return
waitable_event_.TimedWait(base::TimeDelta::FromMilliseconds(50));
nit: Might make sense to name waitable_event_ more specifically

[Mark Seaborn, 2014-07-30 22:23:26]

One thing makes me nervous about this:  LOG_FATAL is sometimes called in cases
where something unexpected happened and we want to exit as soon as possible,
because a bug might have been tickled (e.g. memory corruption) and we want to
avoid making it exploitable.  The more complex the handling of LOG_FATAL, the
more likely the bug will become exploitable.

Could you possibly add test coverage for this?  That would make me worry less
about invoking LOG_FATAL being risky.

If you need a way to cause a LOG_FATAL in a test, you could call the
test_crash() syscall with NACL_TEST_CRASH_LOG_FATAL.

https://codereview.chromium.org/424893003/diff/140001/components/nacl/common/...
File components/nacl/common/nacl_messages.h (right):

https://codereview.chromium.org/424893003/diff/140001/components/nacl/common/...
components/nacl/common/nacl_messages.h:107:
IPC_MESSAGE_CONTROL1(NaClProcessHostMsg_FatalLogReceived,
Isn't the "NaClProcessHostMsg_" prefix for messages sent to NaClProcessHost in
the browser?  I think you want a different prefix for messages sent to the
renderer.

https://codereview.chromium.org/424893003/diff/140001/components/nacl/loader/...
File components/nacl/loader/nacl_trusted_listener.cc (right):

https://codereview.chromium.org/424893003/diff/140001/components/nacl/loader/...
components/nacl/loader/nacl_trusted_listener.cc:59: ipc_task_runner_->PostTask(
So ipc_task_runner is io_thread_.message_loop_proxy().get() from
nacl_listener.cc.

Do we ever run native_client code on the IO thread, e.g. for handling Chrome
IPC?  If so, the wait below would time out and the error won't be reported.

[teravest, 2014-07-30 22:37:24]

On Wed, Jul 30, 2014 at 4:23 PM,  <mseaborn@chromium.org> wrote:
> One thing makes me nervous about this:  LOG_FATAL is sometimes called in
> cases
> where something unexpected happened and we want to exit as soon as possible,
> because a bug might have been tickled (e.g. memory corruption) and we want
> to
> avoid making it exploitable.  The more complex the handling of LOG_FATAL,
> the
> more likely the bug will become exploitable.

This is a feature most users won't care about. We could put this
feature under a flag, but it will add one more step for debugging NaCl
issues. Would that address your concerns about exploits?

>
> Could you possibly add test coverage for this?  That would make me worry
> less
> about invoking LOG_FATAL being risky.
>
> If you need a way to cause a LOG_FATAL in a test, you could call the
> test_crash() syscall with NACL_TEST_CRASH_LOG_FATAL.
>
>
>
https://codereview.chromium.org/424893003/diff/140001/components/nacl/common/...
> File components/nacl/common/nacl_messages.h (right):
>
>
https://codereview.chromium.org/424893003/diff/140001/components/nacl/common/...
> components/nacl/common/nacl_messages.h:107:
> IPC_MESSAGE_CONTROL1(NaClProcessHostMsg_FatalLogReceived,
> Isn't the "NaClProcessHostMsg_" prefix for messages sent to
> NaClProcessHost in the browser?  I think you want a different prefix for
> messages sent to the renderer.
>
>
>
https://codereview.chromium.org/424893003/diff/140001/components/nacl/loader/...
> File components/nacl/loader/nacl_trusted_listener.cc (right):
>
>
https://codereview.chromium.org/424893003/diff/140001/components/nacl/loader/...
> components/nacl/loader/nacl_trusted_listener.cc:59:
> ipc_task_runner_->PostTask(
> So ipc_task_runner is io_thread_.message_loop_proxy().get() from
> nacl_listener.cc.
>
> Do we ever run native_client code on the IO thread, e.g. for handling
> Chrome IPC?  If so, the wait below would time out and the error won't be
> reported.
>
> https://codereview.chromium.org/424893003/

To unsubscribe from this group and stop receiving emails from it, send an email
to chromium-reviews+unsubscribe@chromium.org.

[Mark Seaborn, 2014-08-07 15:59:24]

On 30 July 2014 15:37, Justin TerAvest <teravest@chromium.org> wrote:

> On Wed, Jul 30, 2014 at 4:23 PM,  <mseaborn@chromium.org> wrote:
> > One thing makes me nervous about this:  LOG_FATAL is sometimes called in
> > cases
> > where something unexpected happened and we want to exit as soon as
> possible,
> > because a bug might have been tickled (e.g. memory corruption) and we
> want
> > to
> > avoid making it exploitable.  The more complex the handling of LOG_FATAL,
> > the
> > more likely the bug will become exploitable.
>
> This is a feature most users won't care about. We could put this
> feature under a flag, but it will add one more step for debugging NaCl
> issues. Would that address your concerns about exploits?


It would be a shame if this regressed so that it no longer works by
default.  While most users don't necessarily want to use this, we *do* want
to debug problems that occur on normal users' machines.  It's useful to be
able to tell users to copy+paste log messages from the Javascript console.
 We don't want to have to tell them to enable a flag, and that wouldn't
necessarily help for rare flaky failures anyway.  Also, debugging NaCl is
difficult enough already even for developers, so I wouldn't want to make it
harder.

Either of two things would make me happier:

 1) If you added a test for this logging.  How difficult would this be?  To
generate a LOG_FATAL error, maybe you could make nacl_listener.cc call
NaClLog()+LOG_FATAL if a "NACL_TEST_CRASH" env var is set?

 2) If the log data were sent back via shared memory rather than Chrome
IPC.  The idea would be to send a small shared memory segment to the NaCl
process on startup.  The NaCl process would mmap() it on startup.  On a
LOG_FATAL, it would memcpy() the log data into the mmap'd area.  (This
would be safer because memcpy() is much less likely to go wrong than
entering an event loop and doing Chrome IPC.)  When the renderer sees the
NaCl process has exited, it would read() the log data from the shared
memory.

Setting up a shared memory segment for this would be quite useful, because
we could use it for other failure reporting too.  For example, when a NaCl
process exits, we currently don't do any logging in the Javascript console
to indicate why.  It would be nice to indicate whether it was a crash in
untrusted code, and if so, dump the register state.  On Windows, it would
be rather difficult to do this via Chrome IPC, but we could easily change
NaCl's NTDLL patch to dump the register state into shared memory.

Cheers,
Mark

To unsubscribe from this group and stop receiving emails from it, send an email
to chromium-reviews+unsubscribe@chromium.org.

[teravest, 2014-08-12 21:37:54]

I spent some time trying to add a test for this. It turns out that
it's not easy to inspect the contents of the javascript console. I
tried copying what was done for some other tests, but it takes a
different codepath, so I can't use that strategy here.

The other console behavior is here:

https://code.google.com/p/chromium/codesearch#chromium/src/content/browser/fr...
...and tests hook the logging infrastructure, looking for a write from
the file "CONSOLE".

I could look at changing HostGlobals, though I don't want to touch
that much since it's used by other things that write to the JS
console. I don't see how to inject something like TestGlobals in an
integration test.


I suppose I'll look at using shared memory, though I don't like that
this is getting more complicated.


On Thu, Aug 7, 2014 at 9:59 AM, Mark Seaborn <mseaborn@chromium.org> wrote:
> On 30 July 2014 15:37, Justin TerAvest <teravest@chromium.org> wrote:
>>
>> On Wed, Jul 30, 2014 at 4:23 PM,  <mseaborn@chromium.org> wrote:
>> > One thing makes me nervous about this:  LOG_FATAL is sometimes called in
>> > cases
>> > where something unexpected happened and we want to exit as soon as
>> > possible,
>> > because a bug might have been tickled (e.g. memory corruption) and we
>> > want
>> > to
>> > avoid making it exploitable.  The more complex the handling of
>> > LOG_FATAL,
>> > the
>> > more likely the bug will become exploitable.
>>
>> This is a feature most users won't care about. We could put this
>> feature under a flag, but it will add one more step for debugging NaCl
>> issues. Would that address your concerns about exploits?
>
>
> It would be a shame if this regressed so that it no longer works by default.
> While most users don't necessarily want to use this, we *do* want to debug
> problems that occur on normal users' machines.  It's useful to be able to
> tell users to copy+paste log messages from the Javascript console.  We don't
> want to have to tell them to enable a flag, and that wouldn't necessarily
> help for rare flaky failures anyway.  Also, debugging NaCl is difficult
> enough already even for developers, so I wouldn't want to make it harder.
>
> Either of two things would make me happier:
>
>  1) If you added a test for this logging.  How difficult would this be?  To
> generate a LOG_FATAL error, maybe you could make nacl_listener.cc call
> NaClLog()+LOG_FATAL if a "NACL_TEST_CRASH" env var is set?
>
>  2) If the log data were sent back via shared memory rather than Chrome IPC.
> The idea would be to send a small shared memory segment to the NaCl process
> on startup.  The NaCl process would mmap() it on startup.  On a LOG_FATAL,
> it would memcpy() the log data into the mmap'd area.  (This would be safer
> because memcpy() is much less likely to go wrong than entering an event loop
> and doing Chrome IPC.)  When the renderer sees the NaCl process has exited,
> it would read() the log data from the shared memory.
>
> Setting up a shared memory segment for this would be quite useful, because
> we could use it for other failure reporting too.  For example, when a NaCl
> process exits, we currently don't do any logging in the Javascript console
> to indicate why.  It would be nice to indicate whether it was a crash in
> untrusted code, and if so, dump the register state.  On Windows, it would be
> rather difficult to do this via Chrome IPC, but we could easily change
> NaCl's NTDLL patch to dump the register state into shared memory.
>
> Cheers,
> Mark
>

To unsubscribe from this group and stop receiving emails from it, send an email
to chromium-reviews+unsubscribe@chromium.org.

[teravest, 2014-08-14 18:14:09]

I wrote a change this morning that uses shared memory for reporting crash
information. It tests okay so far locally on my linux machine. I'll mail it out
as a separate change from this one since it's significantly different.

[teravest, 2014-08-20 19:31:11]

I'm closing this issue in favor of the shared memory approach in
  https://codereview.chromium.org/469423002/