NaCl: Send fatal log messages via shared memory.

NaCl: Send fatal log messages via shared memory.

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 uses a shared memory segment instead of IPC, since something bad may have
happened in the plugin process, so we'd like to keep the behavior for handling
that case as simple as possible. For that reason, the shared memory segment is
mapped before the nexe is loaded.

I've tested this locally by calling RemoteLog(LOG_FATAL, ...) after StartModule
in ServiceRuntime, though I'd like to find some better way to test this as
there's a decent amount of logic here.

BUG=391039
R=jschuh@chromium.org, mseaborn@chromium.org

Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=290910

[Mark Seaborn, 2014-08-17 20:13:45]

Regarding testing: I wonder if it would be possible to at least exercise the
LOG_FATAL case in a test, even if the test doesn't check that the message
appears on the JS console?  Then at least we'd be testing that the renderer
doesn't crash if this code path goes wrong.  (If we insert a renderer crash into
the new code path, does any existing test catch that?)

https://codereview.chromium.org/469423002/diff/1/components/nacl/browser/nacl...
File components/nacl/browser/nacl_process_host.cc (right):

https://codereview.chromium.org/469423002/diff/1/components/nacl/browser/nacl...
components/nacl/browser/nacl_process_host.cc:341:
base::SharedMemory::CloseHandle(crash_info_shmem_plugin_handle_);
Is this a handle in another process's handle namespace?  This looks unsafe on
Windows.

https://codereview.chromium.org/469423002/diff/1/components/nacl/browser/nacl...
components/nacl/browser/nacl_process_host.cc:487:
crash_info_shmem.ShareToProcess(process_->GetData().handle,
Should this check for an error?

https://codereview.chromium.org/469423002/diff/1/components/nacl/loader/nacl_...
File components/nacl/loader/nacl_listener.cc (right):

https://codereview.chromium.org/469423002/diff/1/components/nacl/loader/nacl_...
components/nacl/loader/nacl_listener.cc:55:
memcpy(g_listener->crash_info_shmem_memory(), &bytes, sizeof(bytes));
On Windows, sizeof(bytes) might be different in the NaCl process and the browser
process.  Better to use uint32_t instead?

https://codereview.chromium.org/469423002/diff/1/components/nacl/loader/nacl_...
components/nacl/loader/nacl_listener.cc:284: if
(crash_info_shmem_->Map(nacl::kNaClCrashInfoShmemSize))
Can we make this
CHECK(crash_info_shmem_->Map(nacl::kNaClCrashInfoShmemSize));
?

Otherwise, falling back and ignoring errors would hide bugs.

https://codereview.chromium.org/469423002/diff/1/components/nacl/renderer/nex...
File components/nacl/renderer/nexe_load_manager.cc (right):

https://codereview.chromium.org/469423002/diff/1/components/nacl/renderer/nex...
components/nacl/renderer/nexe_load_manager.cc:269: memcpy(&crash_log_length,
shmem.memory(), sizeof(crash_log_length));
To be safe, this memory access needs to be marked "volatile", i.e.
  crash_log_length = *(volatile uint32_t *) shmem.memory()

Otherwise, the compiler could introduce a TOCTTOU race.

[teravest, 2014-08-18 16:16:26]

Hmm. Since this change uses shared memory instead of sending the data over IPC,
Chrome gets crash information from the plugin only after it's reported via the
reverse service channel closing. This makes it hard (impossible) to trigger a
fatal message from nacl_listener.cc.

I think I'd have to make another change in the NaCl repo to induce a crash if an
environment variable is present-- there's no place to inject code in
nacl_listener.cc to run after the reverse service is brought up.

https://codereview.chromium.org/469423002/diff/1/components/nacl/browser/nacl...
File components/nacl/browser/nacl_process_host.cc (right):

https://codereview.chromium.org/469423002/diff/1/components/nacl/browser/nacl...
components/nacl/browser/nacl_process_host.cc:341:
base::SharedMemory::CloseHandle(crash_info_shmem_plugin_handle_);
On 2014/08/17 20:13:45, Mark Seaborn wrote:
> Is this a handle in another process's handle namespace?  This looks unsafe on
> Windows.

Good point. I've changed this to only share the shared memory before sending
messages to the plugin or the renderer. This means that the object hangs around
longer in the browser, but keeping an extra handle in that process doesn't seem
terrible.

https://codereview.chromium.org/469423002/diff/1/components/nacl/browser/nacl...
components/nacl/browser/nacl_process_host.cc:487:
crash_info_shmem.ShareToProcess(process_->GetData().handle,
On 2014/08/17 20:13:45, Mark Seaborn wrote:
> Should this check for an error?

I've added error checking at the ShareToProcess() calls.

https://codereview.chromium.org/469423002/diff/1/components/nacl/loader/nacl_...
File components/nacl/loader/nacl_listener.cc (right):

https://codereview.chromium.org/469423002/diff/1/components/nacl/loader/nacl_...
components/nacl/loader/nacl_listener.cc:55:
memcpy(g_listener->crash_info_shmem_memory(), &bytes, sizeof(bytes));
On 2014/08/17 20:13:45, Mark Seaborn wrote:
> On Windows, sizeof(bytes) might be different in the NaCl process and the
browser
> process.  Better to use uint32_t instead?

Done.

https://codereview.chromium.org/469423002/diff/1/components/nacl/loader/nacl_...
components/nacl/loader/nacl_listener.cc:284: if
(crash_info_shmem_->Map(nacl::kNaClCrashInfoShmemSize))
On 2014/08/17 20:13:45, Mark Seaborn wrote:
> Can we make this
> CHECK(crash_info_shmem_->Map(nacl::kNaClCrashInfoShmemSize));
> ?
> 
> Otherwise, falling back and ignoring errors would hide bugs.

Done.

https://codereview.chromium.org/469423002/diff/1/components/nacl/renderer/nex...
File components/nacl/renderer/nexe_load_manager.cc (right):

https://codereview.chromium.org/469423002/diff/1/components/nacl/renderer/nex...
components/nacl/renderer/nexe_load_manager.cc:269: memcpy(&crash_log_length,
shmem.memory(), sizeof(crash_log_length));
On 2014/08/17 20:13:45, Mark Seaborn wrote:
> To be safe, this memory access needs to be marked "volatile", i.e.
>   crash_log_length = *(volatile uint32_t *) shmem.memory()
> 
> Otherwise, the compiler could introduce a TOCTTOU race.

Done.

[Mark Seaborn, 2014-08-18 19:04:09]

LGTM

https://codereview.chromium.org/469423002/diff/20001/components/nacl/browser/...
File components/nacl/browser/nacl_process_host.cc (right):

https://codereview.chromium.org/469423002/diff/20001/components/nacl/browser/...
components/nacl/browser/nacl_process_host.cc:748: }
How about doing
  crash_info_shmem_.Close()
to unref the handle after we've sent it to both child processes?

https://codereview.chromium.org/469423002/diff/20001/components/nacl/common/n...
File components/nacl/common/nacl_types.h (right):

https://codereview.chromium.org/469423002/diff/20001/components/nacl/common/n...
components/nacl/common/nacl_types.h:42: // the plugin and the renderer.
How about: "from trusted code in the NaCl process to the renderer"

This makes the direction explicit.

"Plugin" is ambiguous, so it's better to say "the NaCl process".

https://codereview.chromium.org/469423002/diff/20001/components/nacl/common/n...
components/nacl/common/nacl_types.h:71: // For plugin <-> renderer crash
information reporting.
"NaCl -> renderer"

https://codereview.chromium.org/469423002/diff/20001/components/nacl/common/n...
components/nacl/common/nacl_types.h:143: // For plugin <-> renderer crash
information reporting.
Ditto

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

https://codereview.chromium.org/469423002/diff/20001/components/nacl/loader/n...
components/nacl/loader/nacl_listener.cc:49: namespace {
Nit: Add empty line after this to match end of namespace block

https://codereview.chromium.org/469423002/diff/20001/components/nacl/loader/n...
components/nacl/loader/nacl_listener.cc:53: uint32_t copy_bytes =
std::min<uint32_t>(bytes,
How about commenting: use uint32_t rather than size_t for the case when the
browser and NaCl processes are a mix of 32-bit and 64-bit processes.

https://codereview.chromium.org/469423002/diff/20001/components/nacl/renderer...
File components/nacl/renderer/nexe_load_manager.cc (right):

https://codereview.chromium.org/469423002/diff/20001/components/nacl/renderer...
components/nacl/renderer/nexe_load_manager.cc:269: crash_log_length = *(volatile
uint32_t *) shmem.memory();
Nit: this should probably be a C++-style cast

Also, can you comment the reason for the use of 'volatile'?

https://codereview.chromium.org/469423002/diff/20001/components/nacl/renderer...
components/nacl/renderer/nexe_load_manager.cc:270: memcpy(&crash_log_length,
shmem.memory(), sizeof(uint32_t));
Redundant -- you forgot to remove this.

https://codereview.chromium.org/469423002/diff/20001/components/nacl/renderer...
components/nacl/renderer/nexe_load_manager.cc:274: char
crash_log_data[kNaClCrashInfoShmemSize];
Let's not allocate this on the stack, since this is big(ish), especially given
that this doesn't have test coverage.

Can you use a heap-allocated scoped array, please?  (With
base/memory/scoped_vector.h perhaps.)

https://codereview.chromium.org/469423002/diff/20001/components/nacl/renderer...
components/nacl/renderer/nexe_load_manager.cc:276: (char*) shmem.memory() +
sizeof(uint32_t),
Nit: use C++ cast

[teravest, 2014-08-18 21:21:19]

+jschuh for components/nacl/common/nacl_host_messages.h and
components/nacl/common/nacl_messages.h

[Mark Seaborn, 2014-08-19 03:40:07]

On 18 August 2014 09:16, <teravest@chromium.org> wrote:

> Hmm. Since this change uses shared memory instead of sending the data over
> IPC,
> Chrome gets crash information from the plugin only after it's reported via
> the
> reverse service channel closing. This makes it hard (impossible) to
> trigger a
> fatal message from nacl_listener.cc.
>

Hmm, really?  Doesn't that mean it won't be triggered for a lot of possible
startup crashes?  Are there any current error conditions that trigger it?

Maybe you could test this by calling the test_crash() syscall with
NACL_TEST_CRASH_LOG_FATAL (as I suggested in
https://codereview.chromium.org/424893003/#msg5)?  That triggers a
LOG_FATAL exit.

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-19 04:48:08]

On Mon, Aug 18, 2014 at 9:39 PM, Mark Seaborn <mseaborn@chromium.org> wrote:
> On 18 August 2014 09:16, <teravest@chromium.org> wrote:
>>
>> Hmm. Since this change uses shared memory instead of sending the data over
>> IPC,
>> Chrome gets crash information from the plugin only after it's reported via
>> the
>> reverse service channel closing. This makes it hard (impossible) to
>> trigger a
>> fatal message from nacl_listener.cc.
>
>
> Hmm, really?  Doesn't that mean it won't be triggered for a lot of possible
> startup crashes?  Are there any current error conditions that trigger it?

This patchset should give functionality equivalent to what's provided
today-- the signal for crashing is the same; this is effectively just
changing the retrieval mechanism from SRPC to shared memory.

I think it's possible that the code could be improved to report plugin
crashes from a wider area of code, but I don't think that needs to
happen as part of this change.


>
> Maybe you could test this by calling the test_crash() syscall with
> NACL_TEST_CRASH_LOG_FATAL (as I suggested in
> https://codereview.chromium.org/424893003/#msg5)?  That triggers a LOG_FATAL
> exit.

I can do that, but what's the advantage of that over the testing I did
with manually calling RemoteLog() from service_runtime.cc in the
trusted plugin? I've confirmed that this codepath is hit from a
LOG_FATAL message from that codepath.

>
> Cheers,
> Mark
>

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

[Mark Seaborn, 2014-08-19 14:32:31]

On 18 August 2014 21:47, Justin TerAvest <teravest@chromium.org> wrote:

> On Mon, Aug 18, 2014 at 9:39 PM, Mark Seaborn <mseaborn@chromium.org>
> wrote:
> > On 18 August 2014 09:16, <teravest@chromium.org> wrote:
> >>
> >> Hmm. Since this change uses shared memory instead of sending the data
> over
> >> IPC,
> >> Chrome gets crash information from the plugin only after it's reported
> via
> >> the
> >> reverse service channel closing. This makes it hard (impossible) to
> >> trigger a
> >> fatal message from nacl_listener.cc.
> >
> >
> > Hmm, really?  Doesn't that mean it won't be triggered for a lot of
> possible
> > startup crashes?  Are there any current error conditions that trigger it?
>
> This patchset should give functionality equivalent to what's provided
> today-- the signal for crashing is the same; this is effectively just
> changing the retrieval mechanism from SRPC to shared memory.
>
> I think it's possible that the code could be improved to report plugin
> crashes from a wider area of code, but I don't think that needs to
> happen as part of this change.
>

To clarify, I wasn't asking you to add a test as part of this CL, which is
why I LG'd it already.  I was just discussing how an automated test could
be added, and trying to understand when the existing code does and doesn't
report failures.


> >
> > Maybe you could test this by calling the test_crash() syscall with
> > NACL_TEST_CRASH_LOG_FATAL (as I suggested in
> > https://codereview.chromium.org/424893003/#msg5)?  That triggers a
> LOG_FATAL
> > exit.
>
> I can do that, but what's the advantage of that over the testing I did
> with manually calling RemoteLog() from service_runtime.cc in the
> trusted plugin? I've confirmed that this codepath is hit from a
> LOG_FATAL message from that codepath.


The advantage would be that it can be used from an automated test already
without changing anything on the NaCl side.

Cheers,
Mark

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

[jschuh, 2014-08-19 15:39:22]

Is there anything that can go wrong if the log spews arbitrary content (e.g.
control characters, HTML, script, etc.) to the console, or does all of that get
escaped.

[teravest, 2014-08-19 17:10:47]

On 2014/08/19 15:39:22, Justin Schuh wrote:
> Is there anything that can go wrong if the log spews arbitrary content (e.g.
> control characters, HTML, script, etc.) to the console, or does all of that
get
> escaped.

It looks pretty safe to me, after some manual testing.

I tried injecting HTML and JS, neither of which were evaluated; the text was
just added to the console log.

For control characters, it depends on the value. '\n' starts a new line, and
'\t' inserts a tab character. 0x7f (DEL) appears to be ignored. '\a' (terminal
bell) did nothing in the browser, but caused a terminal bell in the browser
running Chrome.

Testing with the invalid UTF-8 sequence "\xc3\x28" caused the values U+FFFD
(replacement character) and "(" (0x28) to be printed to the console, which seems
reasonable to me.

[teravest, 2014-08-19 19:58:17]

https://codereview.chromium.org/469423002/diff/20001/components/nacl/browser/...
File components/nacl/browser/nacl_process_host.cc (right):

https://codereview.chromium.org/469423002/diff/20001/components/nacl/browser/...
components/nacl/browser/nacl_process_host.cc:748: }
On 2014/08/18 19:04:08, Mark Seaborn wrote:
> How about doing
>   crash_info_shmem_.Close()
> to unref the handle after we've sent it to both child processes?

Done.

https://codereview.chromium.org/469423002/diff/20001/components/nacl/common/n...
File components/nacl/common/nacl_types.h (right):

https://codereview.chromium.org/469423002/diff/20001/components/nacl/common/n...
components/nacl/common/nacl_types.h:42: // the plugin and the renderer.
On 2014/08/18 19:04:08, Mark Seaborn wrote:
> How about: "from trusted code in the NaCl process to the renderer"
> 
> This makes the direction explicit.
> 
> "Plugin" is ambiguous, so it's better to say "the NaCl process".

Done.

https://codereview.chromium.org/469423002/diff/20001/components/nacl/common/n...
components/nacl/common/nacl_types.h:71: // For plugin <-> renderer crash
information reporting.
On 2014/08/18 19:04:09, Mark Seaborn wrote:
> "NaCl -> renderer"

Done.

https://codereview.chromium.org/469423002/diff/20001/components/nacl/common/n...
components/nacl/common/nacl_types.h:143: // For plugin <-> renderer crash
information reporting.
On 2014/08/18 19:04:08, Mark Seaborn wrote:
> Ditto

Done.

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

https://codereview.chromium.org/469423002/diff/20001/components/nacl/loader/n...
components/nacl/loader/nacl_listener.cc:49: namespace {
On 2014/08/18 19:04:09, Mark Seaborn wrote:
> Nit: Add empty line after this to match end of namespace block

Done.

https://codereview.chromium.org/469423002/diff/20001/components/nacl/loader/n...
components/nacl/loader/nacl_listener.cc:53: uint32_t copy_bytes =
std::min<uint32_t>(bytes,
On 2014/08/18 19:04:09, Mark Seaborn wrote:
> How about commenting: use uint32_t rather than size_t for the case when the
> browser and NaCl processes are a mix of 32-bit and 64-bit processes.

Done.

https://codereview.chromium.org/469423002/diff/20001/components/nacl/renderer...
File components/nacl/renderer/nexe_load_manager.cc (right):

https://codereview.chromium.org/469423002/diff/20001/components/nacl/renderer...
components/nacl/renderer/nexe_load_manager.cc:269: crash_log_length = *(volatile
uint32_t *) shmem.memory();
On 2014/08/18 19:04:09, Mark Seaborn wrote:
> Nit: this should probably be a C++-style cast
> 
> Also, can you comment the reason for the use of 'volatile'?

Done.

https://codereview.chromium.org/469423002/diff/20001/components/nacl/renderer...
components/nacl/renderer/nexe_load_manager.cc:270: memcpy(&crash_log_length,
shmem.memory(), sizeof(uint32_t));
On 2014/08/18 19:04:09, Mark Seaborn wrote:
> Redundant -- you forgot to remove this.

Removed.

https://codereview.chromium.org/469423002/diff/20001/components/nacl/renderer...
components/nacl/renderer/nexe_load_manager.cc:274: char
crash_log_data[kNaClCrashInfoShmemSize];
On 2014/08/18 19:04:09, Mark Seaborn wrote:
> Let's not allocate this on the stack, since this is big(ish), especially given
> that this doesn't have test coverage.
> 
> Can you use a heap-allocated scoped array, please?  (With
> base/memory/scoped_vector.h perhaps.)

Changed to use scoped_ptr<char[]>

https://codereview.chromium.org/469423002/diff/20001/components/nacl/renderer...
components/nacl/renderer/nexe_load_manager.cc:276: (char*) shmem.memory() +
sizeof(uint32_t),
On 2014/08/18 19:04:09, Mark Seaborn wrote:
> Nit: use C++ cast

Done.

[Mark Seaborn, 2014-08-19 23:38:51]

https://codereview.chromium.org/469423002/diff/100001/components/nacl/rendere...
File components/nacl/renderer/nexe_load_manager.cc (right):

https://codereview.chromium.org/469423002/diff/100001/components/nacl/rendere...
components/nacl/renderer/nexe_load_manager.cc:276: // char
crash_log_data[kNaClCrashInfoShmemSize];
I think you forgot to remove this.

[jschuh, 2014-08-20 04:16:17]

okay, lgtm for ipc security then

[teravest, 2014-08-20 14:23:28]

https://codereview.chromium.org/469423002/diff/100001/components/nacl/rendere...
File components/nacl/renderer/nexe_load_manager.cc (right):

https://codereview.chromium.org/469423002/diff/100001/components/nacl/rendere...
components/nacl/renderer/nexe_load_manager.cc:276: // char
crash_log_data[kNaClCrashInfoShmemSize];
On 2014/08/19 23:38:51, Mark Seaborn wrote:
> I think you forgot to remove this.

Removed.

[teravest, 2014-08-20 19:21:36]

The CQ bit was checked by teravest@chromium.org

[commit-bot: I haz the power, 2014-08-20 19:24:12]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/teravest@chromium.org/469423002/120001

[teravest, 2014-08-20 20:43:15]

Committed patchset #6 manually as 290910 (presubmit successful).