1348269 - Report on last_warning and last_error from BrokerServices::SpawnTarget.

Status: RESOLVED FIXED

(Core :: Security: Process Sandboxing, enhancement)

Description

[Bob Owen (:bobowen)]

Just noticed during a rebase that I'd forgotten about these two new out params (last_warning and last_error) from SpawnTarget.

We should probably report these in some way, depending on the return value I imagine.
Possibly always report for last_warning.

Comment 1

[Bob Owen (:bobowen)]

I don't think we need to block on this for the current milestone (sbwc2), but I'd like to pick it up soon, so dropping it into sbwc3.

Comment 2

[Alex Gaynor [:Alex_Gaynor]]

(Still learning the code, sorry if this is a question with an obvious answer!) Where were you thinking would be the right place to report these? Looking up the stack, I see the caller prints to EnvironmentLog("MOZ_PROCESS_LOG"); somewhere like that?

Comment 3

[Bob Owen (:bobowen)]

(In reply to Alex Gaynor from comment #2)
> (Still learning the code, sorry if this is a question with an obvious
> answer!) Where were you thinking would be the right place to report these?
> Looking up the stack, I see the caller prints to
> EnvironmentLog("MOZ_PROCESS_LOG"); somewhere like that?

I hadn't put all that much thought into it, just filed so I didn't forget about it. :-)

I think at least we would want to use MOZ_LOG, with the appropriate levels (there's already a LOG_E macro defined).
I'm guessing that |last_error| should only be something other than ERROR_SUCCESS when |result| is false.

It might be useful to add to telemetry [1], to see if there are problems that we're not seeing through bug reports or crashes.
I'm particularly thinking about |last_warning| here, although I haven't looked to see in what circumstances this gets set but the process still starts.

When |result| is false it might make sense to use AnnotateCrashReport as well, as the child process won't have been started and there's a chance this might lead to a crash.

[1] https://gecko.readthedocs.io/en/latest/toolkit/components/telemetry/telemetry/collection/index.html

Comment 4

[Alex Gaynor [:Alex_Gaynor]]

Attachment: Bug 1348269 - When SpawnTarget fails during Windows sandboxed process creation, log more information

Review commit: https://reviewboard.mozilla.org/r/126388/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/126388/

Comment 5

[Bob Owen (:bobowen)]

Comment on attachment 8854455 [details]
Bug 1348269 - When SpawnTarget fails during Windows sandboxed process creation, log more information

https://reviewboard.mozilla.org/r/126388/#review129304

If we're just going to add MOZ_LOG logging in this bug, can you file a follow-up for adding in Telemetry and/or crash reporting annotations, please.

::: commit-message-89198:1
(Diff revision 1)
> +Bug 1348269 - When SpawnTarget fails, log more information

nit: for a bit more context can we add the following after "fails" please: during Windows sandboxed process creation

::: security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:115
(Diff revision 1)
> +    LOG_E("Failed (ResultCode %d) to SpawnTarget with last_error=%d, last_warning=%d",
> +        result, last_error, last_warning);
>      return false;
>    }

Looks like it can only currently happen for lowbox tokens, which we haven't tried to use yet.

However for completeness can we add an:

  } else if (sandbox::SBOX_ALL_OK != last_warning) {

and log the error and warning at Warning level

Comment 6

[Alex Gaynor [:Alex_Gaynor]]

Comment on attachment 8854455 [details]
Bug 1348269 - When SpawnTarget fails during Windows sandboxed process creation, log more information

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/126388/diff/1-2/

Comment 7

[Bob Owen (:bobowen)]

Comment on attachment 8854455 [details]
Bug 1348269 - When SpawnTarget fails during Windows sandboxed process creation, log more information

https://reviewboard.mozilla.org/r/126388/#review129472

Thanks Alex.

::: security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:117
(Diff revisions 1 - 2)
>    DWORD last_error = ERROR_SUCCESS;
>    result = sBrokerService->SpawnTarget(aPath, aArguments, mPolicy,
>                                         &last_warning, &last_error, &targetInfo);
>    if (sandbox::SBOX_ALL_OK != result) {
>      LOG_E("Failed (ResultCode %d) to SpawnTarget with last_error=%d, last_warning=%d",
>          result, last_error, last_warning);

nit: sorry didn't spot this before, please indent to line up with the first parameter above.

Same thing in the LOG_W below.

::: security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:120
(Diff revisions 1 - 2)
>    if (sandbox::SBOX_ALL_OK != result) {
>      LOG_E("Failed (ResultCode %d) to SpawnTarget with last_error=%d, last_warning=%d",
>          result, last_error, last_warning);
>      return false;
> +  } else if (sandbox::SBOX_ALL_OK != last_warning) {
> +    // If these was a warning (but the result was still ok), log it and proceed.

nit: s/these/there/

Comment 8

[Alex Gaynor [:Alex_Gaynor]]

Comment on attachment 8854455 [details]
Bug 1348269 - When SpawnTarget fails during Windows sandboxed process creation, log more information

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/126388/diff/2-3/

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0c17353ada46
When SpawnTarget fails during Windows sandboxed process creation, log more information r=bobowen

Comment 10

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/0c17353ada46