1320458 - MOZ_LOG doesn't work for child processes because of sandboxing on windows

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Comment 1

[Valentin Gosu [:valentin] (he/him)]

Please provide a way to reproduce the bug. From my experience it does work with the child processes.

Comment 2

[Honza Bambas (:mayhemer)]

(In reply to Valentin Gosu [:valentin] from comment #1)
> Please provide a way to reproduce the bug. From my experience it does work
> with the child processes.

Oh, it should work?  Then I'm not sure what happens here:
https://bugzilla.mozilla.org/show_bug.cgi?id=1320360#c8

The guy claims that there are no child process logs produced, but according his about:support e10s is on.  So I'm not sure.  Haven't ever tested myself.

Comment 3

[Valentin Gosu [:valentin] (he/him)]

I just tested on Windows, and indeed, it doesn't seem to create any log files for the child process. I also tested with the regular MOZ_LOG_FILE env variable, and it only seems to create empty files for the child process log files.
The regression seems to be related with the sandboxing. When I changed the sandboxing pref it seemed to work without any issue.

Comment 4

[Honza Bambas (:mayhemer)]

Ah!  Yes, sandboxing.  Something I always forget about.  There is some code that should handle this specific problem, tho, it's probably broken..

Comment 5

[Honza Bambas (:mayhemer)]

This becomes more urgent.  I'm currently experiencing some initial page load issues (using my regular profile with logging on (env vars)) but I'm not able to analyze the logs because there are no logs generated by the content process (and parent seems to behave correctly, so child needs examination).

Comment 6

[Valentin Gosu [:valentin] (he/him)]

(In reply to Honza Bambas (:mayhemer) from comment #5)
> This becomes more urgent.  I'm currently experiencing some initial page load
> issues (using my regular profile with logging on (env vars)) but I'm not
> able to analyze the logs because there are no logs generated by the content
> process (and parent seems to behave correctly, so child needs examination).

You can set security.sandbox.content.level to 0 as a workaround for this.

Comment 7

[Honza Bambas (:mayhemer)]

So, since I don't want to lower sandboxing level for my regular profile I'm enabling logging for (and from a good reason!), I'd like to find a way to actually allow logging output from child process.

This becomes a major issue, see bug 1341032.

Comment 8

[Honza Bambas (:mayhemer)]

Attachment: v1

- windows only, since I don't have an osx/linux box/knowledge in this area (if wanted, followups will be filed)
- allows access specifically to the file MOZ_LOG_FILE envvar specifies for write from a sandboxed process
- from the sec point of view, I checked that when MOZ_LOG_FILE specifies a path to a directory, the process doesn't get access to that whole directory (so that when a malware would specify MOZ_LOG_FILE="c:\" a sandboxed process got access to the whole system drive) ; anyway, double checking from someone know knows the guts here better than me would be more than appropriate :)

Comment 9

[(No longer employed by Mozilla) Aaron Klotz]

Comment on attachment 8839187 [details] [diff] [review]
v1

I'm going to ask Bob to take a look at this now that he's back, since I'm too caught up in a11y-land at the moment...

Comment 10

[Bob Owen (:bobowen)]

Comment on attachment 8839187 [details] [diff] [review]
v1

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

Thanks for picking this up.

::: security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp
@@ +72,5 @@
>    }
>  #endif
>  
> +  // Enable the child process to write log files when setup
> +  wchar_t const* logFileName = _wgetenv(L"MOZ_LOG_FILE");

Can we also include the functionality for NSPR_LOG_FILE [1] here and delete that, please.

I think I put it in GeckoChildProcessHost at the time, because this file was compiled into a separate DLL without xpcom access.
That changed a while ago, so I think here is the best place for it now.

This also allows for relative paths, so we'll need that here as well.

[1] https://hg.mozilla.org/mozilla-central/file/1bc2ad020aee/ipc/glue/GeckoChildProcessHost.cpp#l655

@@ +84,5 @@
> +        }
> +      }
> +    );
> +
> +    if (rotate) {

I didn't know about this, so this wouldn't have worked with my old change.

I don't think we need to add each name, the rules allow a limited wildcard notation [2], so we could just add ".?", I think.
Perhaps with a comment at the definition of kLogRotateFilesNumber that if it were ever increased to more than 10 a new rule would be needed here.

[2] https://hg.mozilla.org/mozilla-central/file/1bc2ad020aee/security/sandbox/chromium/sandbox/win/src/sandbox_policy.h#l227

Comment 11

[Honza Bambas (:mayhemer)]

(In reply to Bob Owen (:bobowen) from comment #10)
> Comment on attachment 8839187 [details] [diff] [review]
> v1
> 
> Review of attachment 8839187 [details] [diff] [review]:

Thanks for the review.

> -----------------------------------------------------------------
> 
> Thanks for picking this up.
> 
> ::: security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp
> @@ +72,5 @@
> >    }
> >  #endif
> >  
> > +  // Enable the child process to write log files when setup
> > +  wchar_t const* logFileName = _wgetenv(L"MOZ_LOG_FILE");
> 
> Can we also include the functionality for NSPR_LOG_FILE [1] here 

Yes.

> and delete
> that, please.

Yes - that was my main source of confusion - that code made me believe that logging on child processes was taken care of.

> 
> I think I put it in GeckoChildProcessHost at the time, because this file was
> compiled into a separate DLL without xpcom access.
> That changed a while ago, so I think here is the best place for it now.

I was just tracing other exceptions for other log files, so it seemed like a good place to me.

> 
> This also allows for relative paths, so we'll need that here as well.

No idea what you mean?

> 
> [1]
> https://hg.mozilla.org/mozilla-central/file/1bc2ad020aee/ipc/glue/
> GeckoChildProcessHost.cpp#l655
> 
> @@ +84,5 @@
> > +        }
> > +      }
> > +    );
> > +
> > +    if (rotate) {
> 
> I didn't know about this, so this wouldn't have worked with my old change.

It's a relatively new thing.

> 
> I don't think we need to add each name, the rules allow a limited wildcard
> notation [2], so we could just add ".?", I think.
> Perhaps with a comment at the definition of kLogRotateFilesNumber that if it
> were ever increased to more than 10 a new rule would be needed here.

Good point, will do that.

> 
> [2]
> https://hg.mozilla.org/mozilla-central/file/1bc2ad020aee/security/sandbox/
> chromium/sandbox/win/src/sandbox_policy.h#l227

Comment 12

[Bob Owen (:bobowen)]

(In reply to Honza Bambas (:mayhemer) from comment #11)
> (In reply to Bob Owen (:bobowen) from comment #10)

> > 
> > This also allows for relative paths, so we'll need that here as well.
> 
> No idea what you mean?

NSPR_LOG_FILE (and I assume MOZ_LOG_FILE) allows you to specify a bare filename or relative path:

file.log
relpath\file.log

It gets created relative to the process's current working dir.

The sandbox policy only allows rules for absolute paths, so we need to cater for that.

Comment 13

[Honza Bambas (:mayhemer)]

Attachment: v2

- using _wfullpath to resolve relative paths (eats already absolute paths well)
- NSPR_LOG_FILE
- removed MaybeAddNsprLogFileAccess from GeckoChildProcessHost.cpp
- .? for rotate (and comment added)

Comment 14

[Bob Owen (:bobowen)]

Comment on attachment 8842113 [details] [diff] [review]
v2

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

Few nits, only not r+ing because of the question over setting the env var in the relative file path case.

::: security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp
@@ +86,5 @@
> +      }
> +    );
> +
> +    wchar_t logFileNameAbs[MAX_PATH + 2];
> +    if (_wfullpath(logFileNameAbs, logFileName, sizeof(logFileNameAbs))) {

My only slight concern about using this is that it appears to allow "../", but if an attacker has got as far as setting environment variables then we are already lost.
As it handles both path types it certainly makes this more readable thanks.

Have you tested this with a relative path?
I thought we would still have to update the env var with the full path like it used to at the end of MaybeAddNsprLogFileAccess. But maybe something has changed.
If we do still need to do it then it should be the path without the .? even if rotate specified.

@@ +92,5 @@
> +        wchar_t logFileNameWild[MAX_PATH + 2];
> +        _snwprintf(logFileNameWild, sizeof(logFileNameWild), L"%s.?", logFileNameAbs);
> +
> +        mPolicy->AddRule(sandbox::TargetPolicy::SUBSYS_FILES,
> +                          sandbox::TargetPolicy::FILES_ALLOW_ANY, logFileNameWild);

nit: extra space indent

@@ +100,5 @@
> +      }
> +    }
> +  }
> +
> +  logFileName = _wgetenv(L"NSPR_LOG_FILE");

Looks like the logging code uses NSPR_LOG_FILE as fall back after MOZ_LOG_FILE [1].
I think we should do the same here and only add one rule.

[1] https://hg.mozilla.org/mozilla-central/file/34c6c2f302e7/xpcom/base/Logging.cpp#l235

::: xpcom/base/Logging.cpp
@@ -34,5 @@
> -// When rotate option is added to the modules list, this is the hardcoded
> -// number of files we create and rotate.  When there is rotate:40,
> -// we will keep four files per process, each limited to 10MB.  Sum is 40MB,
> -// the given limit.
> -const uint32_t kRotateFilesNumber = 4;

Don't think we need to move this any more, we could just add the comment here.
Also I don't think I should be r+ing the name change, could that go in another bug if you still want to do it.

::: xpcom/base/Logging.h
@@ +44,5 @@
> +// number of files we create and rotate.  When there is rotate:40,
> +// we will keep four files per process, each limited to 10MB.  Sum is 40MB,
> +// the given limit.
> +// NOTE: when this is changed to >= 10, SandboxBroker::LaunchApp must update
> +// sandbox file exception rule from logfile.? to logfile.??

If their comment is correct, then strictly speaking I think we'd need both rules or maybe .*
But given that we'll probably never have to do that, let's just say it will need to be updated.

Comment 15

[Honza Bambas (:mayhemer)]

(In reply to Bob Owen (:bobowen) from comment #14)
> > +    if (_wfullpath(logFileNameAbs, logFileName, sizeof(logFileNameAbs))) {
> 
> My only slight concern about using this is that it appears to allow "../",
> but if an attacker has got as far as setting environment variables then we
> are already lost.

Not just "..".  It can be set as "C:\" or "C:\*.*", clearly also not very safe.

Would stat() for the path and checking it's either not existing or is a file be enough of a security check here?

> As it handles both path types it certainly makes this more readable thanks.
> 
> Have you tested this with a relative path?

Of course I did.

> I thought we would still have to update the env var with the full path like
> it used to at the end of MaybeAddNsprLogFileAccess. 

It ends up in fopen, so, no.

> > +  logFileName = _wgetenv(L"NSPR_LOG_FILE");
> 
> Looks like the logging code uses NSPR_LOG_FILE as fall back after
> MOZ_LOG_FILE [1].
> I think we should do the same here and only add one rule.

I know, I wrote it.   And no, NSPR and MOZ logging are two completely different things, so here it needs to be kept separate.  The fallback is there only temporarily (will be removed after few more releases) to land the necessary changes (new MOZ_LOG* vars) and not break existing frameworks/infras using the old NSPR logging vars.

> Don't think we need to move this any more, we could just add the comment
> here.
> Also I don't think I should be r+ing the name change, could that go in
> another bug if you still want to do it.

Yeah, forgot to revert this.  Can be left unpublished.

> > +// NOTE: when this is changed to >= 10, SandboxBroker::LaunchApp must update
> > +// sandbox file exception rule from logfile.? to logfile.??
> 
> If their comment is correct, then strictly speaking I think we'd need both
> rules or maybe .*

Hmm.. yes, you are right.  ".??" doesn't imply ".?" match.  

> But given that we'll probably never have to do that, let's just say it will
> need to be updated.

:)

Comment 16

[Bob Owen (:bobowen)]

(In reply to Honza Bambas (:mayhemer) from comment #15)
> (In reply to Bob Owen (:bobowen) from comment #14)
> > My only slight concern about using this is that it appears to allow "../",
> > but if an attacker has got as far as setting environment variables then we
> > are already lost.
> 
> Not just "..".  It can be set as "C:\" or "C:\*.*", clearly also not very
> safe.
> 
> Would stat() for the path and checking it's either not existing or is a file
> be enough of a security check here?

I was thinking aloud really, I don't think we should worry about it.
If an attacker can set env vars on the parent process, they can turn the sandbox off anyway.
 
> > As it handles both path types it certainly makes this more readable thanks.
> > 
> > Have you tested this with a relative path?
> 
> Of course I did.

Doesn't seem to be working for me, I get a child file for the GPU process because it isn't sandboxed but not for the content process.
The problem is that fopen, eventually hits NtCreateFile, which is hooked by the sandbox [1].
This is where it calls up to the parent.
However with the relative path, we only get a relative path name in object_attributes, so the rule doesn't match and access isn't granted.
If we set the env var to the full path (without the wild card) it works.

[1] https://hg.mozilla.org/mozilla-central/file/66535e831760/security/sandbox/chromium/sandbox/win/src/filesystem_interception.cc#l21

> > > +  logFileName = _wgetenv(L"NSPR_LOG_FILE");
> > 
> > Looks like the logging code uses NSPR_LOG_FILE as fall back after
> > MOZ_LOG_FILE [1].
> > I think we should do the same here and only add one rule.
> 
> I know, I wrote it.   And no, NSPR and MOZ logging are two completely
> different things, so here it needs to be kept separate.  The fallback is
> there only temporarily (will be removed after few more releases) to land the
> necessary changes (new MOZ_LOG* vars) and not break existing
> frameworks/infras using the old NSPR logging vars.

Fair enough.

Comment 17

[Honza Bambas (:mayhemer)]

(In reply to Bob Owen (:bobowen) from comment #16)
> > > Have you tested this with a relative path?
> > 
> > Of course I did.
> 
> Doesn't seem to be working for me, I get a child file for the GPU process
> because it isn't sandboxed but not for the content process.
> The problem is that fopen, eventually hits NtCreateFile, which is hooked by
> the sandbox [1].
> This is where it calls up to the parent.
> However with the relative path, we only get a relative path name in
> object_attributes, so the rule doesn't match and access isn't granted.
> If we set the env var to the full path (without the wild card) it works.
> 
> [1]
> https://hg.mozilla.org/mozilla-central/file/66535e831760/security/sandbox/
> chromium/sandbox/win/src/filesystem_interception.cc#l21
> 

Hmm.. I might not be careful enough when checking on this :(  according the fopen docs it's OK to use a relative path.  fullpath() expands it the same way as fopen should.  but if the rule is checked the way you describe, we need to expand before the fopen call inside Logging.cpp.  That should be easy to fix.

Thanks for catching it.

Comment 18

[Bob Owen (:bobowen)]

(In reply to Honza Bambas (:mayhemer) from comment #17)
> (In reply to Bob Owen (:bobowen) from comment #16)

> Hmm.. I might not be careful enough when checking on this :(  according the
> fopen docs it's OK to use a relative path.  fullpath() expands it the same
> way as fopen should.  but if the rule is checked the way you describe, we
> need to expand before the fopen call inside Logging.cpp.  That should be
> easy to fix.
> 
> Thanks for catching it.

fopen works fine with a relative path.
It's just that the path isn't expanded by the time it hits NtCreateFile, so we can't add a chromium sandbox policy rule for it.
It must be expanded some time after that.

We could change the logging code to expand the path, but just adding |::SetEnvironmentVariableW(L"MOZ_LOG_FILE", logFileNameAbs);| (and the same for NSPR_LOG_FILE) works given that we already have the expanded path.

I don't really mind either way.

Comment 19

[Honza Bambas (:mayhemer)]

Attachment: v3

This time rel paths tested more carefully.  I've added the expansion to GeckoChildProcessHost spawning the child process so we set the env var just once, at one place.

Comment 20

[Randell Jesup [:jesup] (needinfo me)]

Does this affect 52 on any platform?

Comment 21

[Randell Jesup [:jesup] (needinfo me)]

Also: When this lands, file followup bugs for other platforms.  Not being able to get logs from reporters (or ourselves) is a HUGE problem. Since this is also in 53 apparently, we'll need to uplift.

Bob/Jim - can you get someone on fixing this for mac/linux ASAP?  Also, we need to uplift fixes as far as the problem exists (which I imagine is platform/sandbox-level dependent).

Comment 22

[Bob Owen (:bobowen)]

Comment on attachment 8843939 [details] [diff] [review]
v3

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

> This time rel paths tested more carefully.  I've added the expansion to
> GeckoChildProcessHost spawning the child process so we set the env var just
> once, at one place.

Makes sense, thanks.

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/bfe78e7db8fd
Make logging by sandboxed child processes to a file work on Windows, r=aklotz

Comment 24

[Paul Adenot (:padenot)]

I just landed that, we need it for debugging webrtc stuff. I'll now file followups.

Comment 25

[Honza Bambas (:mayhemer)]

(In reply to Paul Adenot (:padenot) from comment #24)
> I just landed that, we need it for debugging webrtc stuff. I'll now file
> followups.

Thanks!

Comment 26

[Bob Owen (:bobowen)]

(In reply to Randell Jesup [:jesup] from comment #20)
> Does this affect 52 on any platform?

I think it will and I dont think this is a regression
As far as I can tell, this has never worked on Windows (at least on Nightly) with the default sandbox policy when MOZ_LOG_FILE was landed.

Comment 27

[Honza Bambas (:mayhemer)]

(In reply to Bob Owen (:bobowen) from comment #26)
> (In reply to Randell Jesup [:jesup] from comment #20)
> > Does this affect 52 on any platform?
> 
> I think it will and I dont think this is a regression
> As far as I can tell, this has never worked on Windows (at least on Nightly)
> with the default sandbox policy when MOZ_LOG_FILE was landed.

MOZ_LOG_FILE is affected on 52.  NSPR_LOG_FILE not, since there is the MaybeAddNsprLogFileAccess which is NSPR specific, never been updated to work also with MOZ_LOG_FILE.  Hmm... as I see it now, it was OK to just update that function (still, just Win specific...)

Comment 29

[Liz Henry (:lizzard) (relman/hg->git project)]

Tracking for 53, if you come up with a fix please request uplift it you think it's reasonable to do.

Comment 30

[Carsten Book [:Tomcat]]

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

Comment 31

[Gerry Chang [:gchang]]

Hi :mayhemer,
Since this bug also affects 53/54, do you think it's worth uplifting to 53/54?

Comment 32

[Honza Bambas (:mayhemer)]

Comment on attachment 8843939 [details] [diff] [review]
v3

Approval Request Comment
[Feature/Bug causing the regression]: bug 1248565
[User impact if declined]: can't get logs from sandboxed child processes when e10s on
[Is this code covered by automated tests?]: no
[Has the fix been verified in Nightly?]: yes
[Needs manual test from QE? If yes, steps to reproduce]:  no
[List of other uplifts needed for the feature/fix]: none
[Is the change risky?]: probably not
[Why is the change risky/not risky?]: we allow writes by sandboxed processes to what is defined in MOZ_LOG_FILE env var.  it can also be C:\*.* which might be pretty dangerous, OTOH, when an attacker can change MOZ_LOG_FILE then he/she can also turn of sandboxing completely
[String changes made/needed]: none

Comment 33

[Gerry Chang [:gchang]]

Comment on attachment 8843939 [details] [diff] [review]
v3

Fix an issue that is unable to get logs from sandboxed child processes when e10s on. Aurora54+ & Beta53+.

Comment 34

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/05c8e1058e98

Comment 35

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/aa07f3afdc87

Comment 36

[Andrei Vaida [:avaida]]

Setting qe-verify- based on Honza's assessment on manual testing needs (see Comment 32).

Comment 37

[Dan Harkless]

I'm using Thunderbird 52.1.1 on Windows 7 64-bit, and I was trying to use the MOZ_LOG* environment variables to debug a mail issue, but when I just set MOZ_LOG, I get no output in the Error Console, and when I additionally set MOZ_LOG_FILE, I always get a zero-length file.  I've tried several variations of the settings (e.g. "SMTP:5,timestamp"), all in line with the syntax from https://wiki.mozilla.org/MailNews:Logging, to no avail.  I don't know if Thunderbird spawns a child process as part of Windows sandboxing, but I wonder if the issue is the same as the one being discussed here.  Has anyone tried Thunderbird logging with 53.* beta builds?  Is it working after the above-discussed fix?  If not, please let me know and I will file a separate bug against Thunderbird specifically.  Thank you.

Comment 38

[Bob Owen (:bobowen)]

(In reply to Dan Harkless from comment #37)
> I'm using Thunderbird 52.1.1 on Windows 7 64-bit, and I was trying to use
> the MOZ_LOG* environment variables to debug a mail issue, but when I just
> set MOZ_LOG, I get no output in the Error Console, and when I additionally
> set MOZ_LOG_FILE, I always get a zero-length file.  I've tried several
> variations of the settings (e.g. "SMTP:5,timestamp"), all in line with the
> syntax from https://wiki.mozilla.org/MailNews:Logging, to no avail.  I don't
> know if Thunderbird spawns a child process as part of Windows sandboxing,
> but I wonder if the issue is the same as the one being discussed here.  Has
> anyone tried Thunderbird logging with 53.* beta builds?  Is it working after
> the above-discussed fix?  If not, please let me know and I will file a
> separate bug against Thunderbird specifically.  Thank you.

Have you tried using the old environment variables NSPR_LOG_MODULES and NSPR_LOG_FILE?
They might work in 52.