1344776 - MOZ_LOG doesn't work for child processes because of sandboxing, other OS but Windows

Status: NEW

(Core :: XPCOM, defect, P3)

Description

[Paul Adenot (:padenot)]

+++ This bug was initially created as a clone of Bug #1320458 +++

https://bugzilla.mozilla.org/show_bug.cgi?id=1320458#c21, this is the osx/linux equivalent of 1320458.

Comment 1

[Paul Adenot (:padenot)]

Bob, do you have a timeline to have this working ? We've converted a bunch of modules to use MOZ_LOG, and now we're kind of stuck without logs.  Would doing something like mayhemer did for windows on other platforms work here, or is there something fishy to take into account for osx and linux ? If it's not too crazy, we can probably do it (someone in the webrtc team), we really need to have working logs.

Comment 2

[Bob Owen (:bobowen)]

Setting up the policy for OS X and Linux are not at all similar.
I'll have to pass this on to haik (for OS X) and gcp (for Linux).

Comment 3

[Haik Aftandilian [:haik]]

(In reply to Paul Adenot (:padenot) from comment #1)
> Bob, do you have a timeline to have this working ? We've converted a bunch
> of modules to use MOZ_LOG, and now we're kind of stuck without logs.  Would
> doing something like mayhemer did for windows on other platforms work here,
> or is there something fishy to take into account for osx and linux ?

Is there a known problem with MOZ_LOG on OS X? I don't think the content sandbox is interfering with it. I've used it to log from content and it seems to work as expected. (Only tried on Nightly.)

Comment 4

[Paul Adenot (:padenot)]

Are we not going to tighten the sandbox so that this issue starts occurring?

Comment 5

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

(In reply to Haik Aftandilian [:haik] from comment #3)
> (In reply to Paul Adenot (:padenot) from comment #1)
> > Bob, do you have a timeline to have this working ? We've converted a bunch
> > of modules to use MOZ_LOG, and now we're kind of stuck without logs.  Would
> > doing something like mayhemer did for windows on other platforms work here,
> > or is there something fishy to take into account for osx and linux ?
> 
> Is there a known problem with MOZ_LOG on OS X? I don't think the content
> sandbox is interfering with it. I've used it to log from content and it
> seems to work as expected. (Only tried on Nightly.)

also, does it work with logging.config.LOG_FILE either when starting, or when changed on the fly?  Also, I've seen AEC logging fail in non-e10s mac as well.

Perhaps it also depends on where MOZ_LOG points to...

Comment 6

[Haik Aftandilian [:haik]]

(In reply to Paul Adenot (:padenot) from comment #4)
> Are we not going to tighten the sandbox so that this issue starts occurring?

On the Mac case, I don't think so. For Mac, we open the log file from the content process at startup before we enable the sandbox and that allows us to write to that specific log file after the sandbox has been enabled. I can't think of anything we'd do that would prevent this from working. In build 52, the Mac content sandbox prevents write access to the home directory, but logging still works because of the way the log file is opened before we enable the sandbox.

Comment 7

[Haik Aftandilian [:haik]]

(In reply to Randell Jesup [:jesup] from comment #5)
> (In reply to Haik Aftandilian [:haik] from comment #3)
> > (In reply to Paul Adenot (:padenot) from comment #1)
> > > Bob, do you have a timeline to have this working ? We've converted a bunch
> > > of modules to use MOZ_LOG, and now we're kind of stuck without logs.  Would
> > > doing something like mayhemer did for windows on other platforms work here,
> > > or is there something fishy to take into account for osx and linux ?
> > 
> > Is there a known problem with MOZ_LOG on OS X? I don't think the content
> > sandbox is interfering with it. I've used it to log from content and it
> > seems to work as expected. (Only tried on Nightly.)
> 
> also, does it work with logging.config.LOG_FILE either when starting, or
> when changed on the fly?  Also, I've seen AEC logging fail in non-e10s mac
> as well.

Ah, OK. It probably doesn't work when the log file is changed on the fly. I'm not very familiar with logging. Aside from setting the MOZ_LOG and MOZ_LOG_FILE environment variable before starting Firefox, what support do we need here?

I didn't know about logging.config.LOG_FILE, but from LogModulePrefWatcher.cpp, it looks like one could change the log file using logging.config.LOG_FILE on the fly and have that take effect. I wonder if that works with e10s pre-Mac-sandboxing (e.g., build 51)? With sandboxing, the child can not open arbitrary files and log to them without cooperating with the parent to open the file on its behalf. There are some whitelisted directories that the content process is allowed to write to.

> Perhaps it also depends on where MOZ_LOG points to...

Since we're opening the file before we turn on sandbox restrictions (for Mac), we should be OK here, but if there are known issues where it's not working, I can look into it.

Comment 8

[Paul Adenot (:padenot)]

(In reply to Haik Aftandilian [:haik] from comment #6)
> (In reply to Paul Adenot (:padenot) from comment #4)
> > Are we not going to tighten the sandbox so that this issue starts occurring?
> 
> On the Mac case, I don't think so. For Mac, we open the log file from the
> content process at startup before we enable the sandbox and that allows us
> to write to that specific log file after the sandbox has been enabled. I
> can't think of anything we'd do that would prevent this from working. In
> build 52, the Mac content sandbox prevents write access to the home
> directory, but logging still works because of the way the log file is opened
> before we enable the sandbox.

Thanks, that's reassuring. A couple questions, though:

- How would we go about allowing the writing domain-specific log-files (such as, in our case, audio streams) to debug on the field ? Sometimes, we see (hear) something strange during a WebRTC call, and we'd like to start dumping various audio streams to debug, while still being in a call. Those issues are hard to catch (usually we don't know what the cause is, maybe it's simply that the spatial configuration of the room where the user is that changed, like a user moving her laptop).
- Do we have the guarantee, for example, that if we use paths generally used for temporary files (such as `/tmp/` or `%USERPROFILE%\AppData\Local\Temp` or something), we can still get log files ?
- I suppose that opening the file before locking down the process prevents being able to dynamically choose the location of the log files, is that correct ?

Restricting the location of those files is probably fine, but we've been in the situation where log files are empty more than once, and it's frustrating to not be able to do anything about an issue a user reports. On the other hand,

Comment 9

[Haik Aftandilian [:haik]]

(In reply to Paul Adenot (:padenot) from comment #8)
> (In reply to Haik Aftandilian [:haik] from comment #6)
> > (In reply to Paul Adenot (:padenot) from comment #4)
> > > Are we not going to tighten the sandbox so that this issue starts occurring?
> > 
> > On the Mac case, I don't think so. For Mac, we open the log file from the
> > content process at startup before we enable the sandbox and that allows us
> > to write to that specific log file after the sandbox has been enabled. I
> > can't think of anything we'd do that would prevent this from working. In
> > build 52, the Mac content sandbox prevents write access to the home
> > directory, but logging still works because of the way the log file is opened
> > before we enable the sandbox.
> 
> Thanks, that's reassuring. A couple questions, though:
> 
> - How would we go about allowing the writing domain-specific log-files (such
> as, in our case, audio streams) to debug on the field ? Sometimes, we see
> (hear) something strange during a WebRTC call, and we'd like to start
> dumping various audio streams to debug, while still being in a call. Those
> issues are hard to catch (usually we don't know what the cause is, maybe
> it's simply that the spatial configuration of the room where the user is
> that changed, like a user moving her laptop).

Is that something you're already doing today?

In order to do that with sandboxing write restrictions, we need the child to be able to ask the parent to open the log file and provide a filehandle that the child can use for logging. Or do logging over IPC.

> - Do we have the guarantee, for example, that if we use paths generally used
> for temporary files (such as `/tmp/` or `%USERPROFILE%\AppData\Local\Temp`
> or something), we can still get log files ?

So far, we haven't set aside a directory that's guaranteed to always be writable and suitable for log files. But that doesn't mean we can't do that if that's the most practical solution.

> - I suppose that opening the file before locking down the process prevents
> being able to dynamically choose the location of the log files, is that
> correct ?

Yes. Linux and Windows might be different.

> Restricting the location of those files is probably fine, but we've been in
> the situation where log files are empty more than once, and it's frustrating
> to not be able to do anything about an issue a user reports. On the other
> hand,

OK.

Comment 10

[Gian-Carlo Pascutto [:gcp]]

(In reply to Haik Aftandilian [:haik] from comment #9)
> So far, we haven't set aside a directory that's guaranteed to always be
> writable and suitable for log files. But that doesn't mean we can't do that
> if that's the most practical solution.

We've discussed (and have on Win and macOS) a specific per-content process tmpdir, but that doesn't help logfiles, I guess.

(All said so far applies to Linux as well, notably opening a file before forking to content will bypass the file broker restrictions)

Comment 11

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

Too late for a fix for 52. Sounds like the real fix may come from bug 1345046 if/when it becomes a priority.

Comment 12

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

This makes me very sad... especially the fix-optional for 54.  

Also (correct me if I'm wrong) -- the above set of comments imply to me that if you change MOZ_LOG dynamically (such as through about:networking) it won't generate a logfile in some platforms/circumstances.

Comment 13

[Jed Davis [:jld] ⟨⏰|UTC-7⟩ ⟦he/him⟧]

(In reply to Randell Jesup [:jesup] from comment #12)
> This makes me very sad... especially the fix-optional for 54.  
> 
> Also (correct me if I'm wrong) -- the above set of comments imply to me that
> if you change MOZ_LOG dynamically (such as through about:networking) it
> won't generate a logfile in some platforms/circumstances.

Yes: the about:networking UI sets a pref, which broadcasts the path to each content process within the pref service, and then each content process tries to fopen() its file directly and probably fails.  On Linux we currently allow writing to /tmp, but that's likely to go away in favor of per-process temp dirs.

Comment 14

[Mike Taylor [:miketaylr]]

This still makes Randell sad.

Comment 15

[BugBot [:suhaib / :marco/ :calixte]]

In the process of migrating remaining bugs to the new severity system, the severity for this bug cannot be automatically determined. Please retriage this bug using the new severity system.

Comment 16

[Jens Stutte [:jstutte]]

(Disclaimer: I did not verify if this is still an issue at all)

I am not sure I see the XPCOM specific part of this. IIUC the similar bug 1320458 seemed to just add a comment to XPCOM files and to handle the logic inside security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp ?

Comment 17

[Paul Adenot (:padenot)]

Logging stuff generally goes in the xpcom component because https://searchfox.org/mozilla-central/source/xpcom/base/Logging.h is in xpcom/base, that's about it.