1430118 - Child process logging doesn't work (again) when sandboxing is on

Status: RESOLVED FIXED

(Core :: Security: Process Sandboxing, defect)

Description

[Honza Bambas (:mayhemer)]

current nightly, latest win10, clean profile.

I'll try to find the reg range.

Comment 1

[Honza Bambas (:mayhemer)]

Works:
https://hg.mozilla.org/mozilla-central/rev/ca379fcca95b1f4a3744242ea8647004b99b3507
Doesn't work:
https://hg.mozilla.org/mozilla-central/rev/e4de69553e3faf8136eb9bb7f2f741e1b7e6f866

Comment 2

[Andrew McCreight [:mccr8]]

I'm assuming that this is hitting because the regressor is a sec bug, rather than it being a security issue itself.

Comment 3

[Andrew McCreight [:mccr8]]

Err, "hidden" instead of "hitting".

Comment 4

[Honza Bambas (:mayhemer)]

(In reply to Andrew McCreight [:mccr8] from comment #2)
> I'm assuming that this is hitting because the regressor is a sec bug, rather
> than it being a security issue itself.
(In reply to Andrew McCreight [:mccr8] from comment #3)
> Err, "hidden" instead of "hitting".

Yes!

Comment 5

[Gian-Carlo Pascutto [:gcp]]

https://hg.mozilla.org/mozilla-central/rev/8fdd1dda7efc#l6.107

Need to check what MOZ_LOG_FILE is in the children.

Comment 6

[Honza Bambas (:mayhemer)]

Note that we append the parent log file name with .child-N extension for each child processe, where N is the increasing number of spawned child processes.

https://hg.mozilla.org/integration/mozilla-inbound/rev/8fdd1dda7efc#l6.55

Comment 7

[Gian-Carlo Pascutto [:gcp]]

I need to check that the code isn't outright broken first. It obviously worked, at some point, but much pain was had trying to get it to compile on all platforms, and especially all 3 Windows compilers. So something might've broken while fixing that.

From the topic, can I assume it works if sandboxing is disabled? That would point to an issue with the 2 different process launch paths on Windows...

Comment 8

[Gian-Carlo Pascutto [:gcp]]

Debugging indicates we're passing the right things to ::CreateProcessAsUserW, i.e. a new env block with MOZ_LOG_FILE properly substituted.

I didn't manage to get MSVC to break into a point right after startup to inspect the log variable, but after my attempts I noticed I had a foobar.txt-child-1 file. Which can only appear if this stuff is actually working?

Comment 9

[Honza Bambas (:mayhemer)]

(In reply to Gian-Carlo Pascutto [:gcp] from comment #8)
> Debugging indicates we're passing the right things to
> ::CreateProcessAsUserW, i.e. a new env block with MOZ_LOG_FILE properly
> substituted.
> 
> I didn't manage to get MSVC to break into a point right after startup to
> inspect the log variable, but after my attempts I noticed I had a
> foobar.txt-child-1 file. Which can only appear if this stuff is actually
> working?

No, it's not working.  I'll get only an empty (zero length) log for child-1 (which is the same as before this bug, not sure what process the first child is..) and then no other child-N (N>1) log file at all.  We fail to open .child-2 and on log files.

Comment 10

[Honza Bambas (:mayhemer)]

You could add a printf somewhere along these lines and see:

https://searchfox.org/mozilla-central/rev/7fb999d1d39418fd331284fab909df076b967ac6/xpcom/base/Logging.cpp#327-339

Comment 11

[Gian-Carlo Pascutto [:gcp]]

Bob Owen pointed out the file that gets written is likely from the unsandboxed GPU process. (The good news is that the argument substitution at least works there)

Couldn't get printf to show up on the console and writing a logfile is unfortunately the subject of the bug. Apparently redirection stdout/stderr to a file might work, or WinDbg. I'll try that next.

Comment 12

[Gian-Carlo Pascutto [:gcp]]

With some tips from jimm I switched to printf_stderr (using OutputDebugString) that allowed me to get some logging from within the sandboxed processes (attaching to them does not seem to work!).

Logging from ContentChild::Init() shows:

[131940] Web Content: MOZ_LOG_FILE=C:\mozilla\mozilla-central\test.txt.child-2
[122108] Web Content: MOZ_LOG_FILE=C:\mozilla\mozilla-central\test.txt.child-3
[106184] Web Content: MOZ_LOG_FILE=C:\mozilla\mozilla-central\test.txt.child-4
[106184] WebExtensions: MOZ_LOG_FILE=C:\mozilla\mozilla-central\test.txt.child-4

And so on. So the environment variables look fine in the child, too. I'm not sure how my bug can be involved, then. I'll check around the regression range.

Comment 13

[Gian-Carlo Pascutto [:gcp]]

<bobowen> gcp: it'll be because this code relies on the variables being changed in the parent https://searchfox.org/mozilla-central/source/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp#215
bobowen> I guess just need to look in the map instead

Comment 14

[Gian-Carlo Pascutto [:gcp]]

I guess we want to do this on Linux as well:
https://searchfox.org/mozilla-central/source/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp#201

Comment 15

[Gian-Carlo Pascutto [:gcp]]

Attachment: Look at the passed environment for logfile names.

Given that this bug is unrelated to the security issue, and the discussion here doesn't have anything revealing, I think it's OK to unhide this bug.

Comment 16

[Bob Owen (:bobowen) PTO until 7th Aug]

Comment on attachment 8943151 [details] [diff] [review]
Look at the passed environment for logfile names.

Review of attachment 8943151 [details] [diff] [review]:
-----------------------------------------------------------------

::: security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp
@@ +16,5 @@
>  #include "mozilla/NSPRLogModulesParser.h"
>  #include "mozilla/UniquePtr.h"
>  #include "mozilla/Telemetry.h"
>  #include "mozilla/WindowsVersion.h"
> +#include "mozilla/ipc/EnvironmentMap.h"

nit: this is already included in the header.

@@ +216,5 @@
>    // Enable the child process to write log files when setup
> +  wchar_t const* logFileName =
> +    aEnvironment[ENVIRONMENT_LITERAL("MOZ_LOG_FILE")].c_str();
> +  if (!logFileName) {
> +    logFileName = _wgetenv(L"MOZ_LOG_FILE");

Can we actually get into a situation where it's not in the map but the env var is present?

Comment 17

[Gian-Carlo Pascutto [:gcp]]

>Can we actually get into a situation where it's not in the map but the env var is present?

Probably not in SandboxBrokers' version of LaunchApp. I'll get rid of the fallback.

Comment 18

[Gian-Carlo Pascutto [:gcp]]

Attachment: Bug 1430118 - Look for log file names in the passed environment.

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

Comment 19

[Bob Owen (:bobowen) PTO until 7th Aug]

Comment on attachment 8943316 [details]
Bug 1430118 - Look for log file names in the passed environment.

https://reviewboard.mozilla.org/r/213628/#review219372

::: security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:217
(Diff revision 1)
>    }
>  #endif
>  
>    // Enable the child process to write log files when setup
> -  wchar_t const* logFileName = _wgetenv(L"MOZ_LOG_FILE");
> +  wchar_t const* logFileName =
> +    aEnvironment[ENVIRONMENT_LITERAL("MOZ_LOG_FILE")].c_str();

Sorry I didn't spot this before, but this is going to add an empty entry into the map if it isn't there already.
We should use find.

Comment 20

[Gian-Carlo Pascutto [:gcp]]

Comment on attachment 8943316 [details]
Bug 1430118 - Look for log file names in the passed environment.

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

Comment 21

[Bob Owen (:bobowen) PTO until 7th Aug]

Comment on attachment 8943316 [details]
Bug 1430118 - Look for log file names in the passed environment.

https://reviewboard.mozilla.org/r/213628/#review219628

It always annoys me how clumsy this is to use in the STL.

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/caae648c5dab
Look for log file names in the passed environment. r=bobowen

Comment 23

[Andrei Ciure[:aciure]]

https://hg.mozilla.org/mozilla-central/rev/caae648c5dab