1193861 - We don't get content processes logged on windows

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Chris Manchester (limited bugmail, email directly)]

Looking at a random recent mochitest-bc-e10s log on windows, we don't have a content process logged when the browser shuts down.

For example in http://ftp.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-win64/1439383387/mozilla-inbound_win8_64_test-mochitest-e10s-browser-chrome-1-bm111-tests1-windows-build1144.txt.gz the end of each has something like (one directory mentions a child process, but it looks like a plugin):

07:07:10     INFO -  TEST-INFO | Main app process: exit status 0
07:07:10     INFO -  runtests.py | Application ran for: 0:00:12.223000
07:07:10     INFO -  zombiecheck | Reading PID log: c:\users\cltbld~1.t-w\appdata\local\temp\tmpzxhpugpidlog
07:07:10     INFO -  Stopping web server
07:07:10     INFO -  Stopping web socket server
07:07:10     INFO -  Stopping ssltunnel

But in a linux log we see something like:

09:17:16     INFO -  TEST-INFO | Main app process: exit 0
09:17:16     INFO -  runtests.py | Application ran for: 0:00:11.901361
09:17:16     INFO -  zombiecheck | Reading PID log: /tmp/tmpARRjj7pidlog
09:17:16     INFO -  ==> process 3374 launched child process 3435
09:17:16     INFO -  zombiecheck | Checking for orphan process with PID: 3435
09:17:16     INFO -  Stopping web server
09:17:16     INFO -  Stopping web socket server
09:17:16     INFO -  Stopping ssltunnel

for even very short running directories.

Comment 1

[Chris Manchester (limited bugmail, email directly)]

I have a patch for this (content processes are launched from the sanboxbroker now, so the logging needs to move), but I'm going to investigate whether using psutil for this is realistic before proceeding.

Comment 2

[Chris Manchester (limited bugmail, email directly)]

Attachment: MozReview Request: Bug 1193861 - Add process launch logging for child processes initiated by the sanbox so test harnesses can track them.

Bug 1193861 - Add process launch logging for child processes initiated by the sanbox so test harnesses can track them.

Comment 3

[Chris Manchester (limited bugmail, email directly)]

I posted the commits I used to fix this for posterity, but now that we have psutil everywhere that seems like the way to go for tracking child processes.

Comment 5

[Bob Owen (:bobowen)]

(In reply to Chris Manchester [:chmanchester] from comment #3)
> I posted the commits I used to fix this for posterity, but now that we have
> psutil everywhere that seems like the way to go for tracking child processes.

Hi Chris, I'm not quite clear will the work on bug 1143547 fix this or is there another problem that will need a separate solution.

Comment 6

[Chris Manchester (limited bugmail, email directly)]

(In reply to Bob Owen (:bobowen) from comment #5)
> (In reply to Chris Manchester [:chmanchester] from comment #3)
> > I posted the commits I used to fix this for posterity, but now that we have
> > psutil everywhere that seems like the way to go for tracking child processes.
> 
> Hi Chris, I'm not quite clear will the work on bug 1143547 fix this or is
> there another problem that will need a separate solution.

Given this and bug 950401 it turned out to be easier to get the python psutil package installed on our testers to address bug 1143547. That's not going to fix this the process log (mccr8 referred to other uses for the log in bug 1243950). 

This log would contain every process the browser launches while it's running, I think we can only get the ones that are still alive from psutil.

Comment 7

[Bob Owen (:bobowen)]

(In reply to Chris Manchester [:chmanchester] from comment #6)
> (In reply to Bob Owen (:bobowen) from comment #5)
> > (In reply to Chris Manchester [:chmanchester] from comment #3)
> > > I posted the commits I used to fix this for posterity, but now that we have
> > > psutil everywhere that seems like the way to go for tracking child processes.
> > 
> > Hi Chris, I'm not quite clear will the work on bug 1143547 fix this or is
> > there another problem that will need a separate solution.
> 
> Given this and bug 950401 it turned out to be easier to get the python
> psutil package installed on our testers to address bug 1143547. That's not
> going to fix this the process log (mccr8 referred to other uses for the log
> in bug 1243950). 
> 
> This log would contain every process the browser launches while it's
> running, I think we can only get the ones that are still alive from psutil.

Ah, OK.

So, how hard would it be to get the logging to go into AppData\LocalLow on Windows instead of AppData\Local?

This would work for the moment.
Given this and another bug mccr8 asked me about, I'm actually wondering whether we want to add some mechanism for the test runners to specify sandbox file policy rules somehow.

Comment 8

[Chris Manchester (limited bugmail, email directly)]

(In reply to Bob Owen (:bobowen) from comment #7)
> (In reply to Chris Manchester [:chmanchester] from comment #6)
> > (In reply to Bob Owen (:bobowen) from comment #5)
> > > (In reply to Chris Manchester [:chmanchester] from comment #3)
> > > > I posted the commits I used to fix this for posterity, but now that we have
> > > > psutil everywhere that seems like the way to go for tracking child processes.
> > > 
> > > Hi Chris, I'm not quite clear will the work on bug 1143547 fix this or is
> > > there another problem that will need a separate solution.
> > 
> > Given this and bug 950401 it turned out to be easier to get the python
> > psutil package installed on our testers to address bug 1143547. That's not
> > going to fix this the process log (mccr8 referred to other uses for the log
> > in bug 1243950). 
> > 
> > This log would contain every process the browser launches while it's
> > running, I think we can only get the ones that are still alive from psutil.
> 
> Ah, OK.
> 
> So, how hard would it be to get the logging to go into AppData\LocalLow on
> Windows instead of AppData\Local?

Not sure. We set the path for the process log here: https://dxr.mozilla.org/mozilla-central/rev/aa90f482e16db77cdb7dea84564ea1cbd8f7f6b3/testing/mochitest/runtests.py#1897

> 
> This would work for the moment.
> Given this and another bug mccr8 asked me about, I'm actually wondering
> whether we want to add some mechanism for the test runners to specify
> sandbox file policy rules somehow.

Comment 9

[Bob Owen (:bobowen)]

(In reply to Chris Manchester [:chmanchester] from comment #8)
> (In reply to Bob Owen (:bobowen) from comment #7)

> Not sure. We set the path for the process log here:
> https://dxr.mozilla.org/mozilla-central/rev/
> aa90f482e16db77cdb7dea84564ea1cbd8f7f6b3/testing/mochitest/runtests.py#1897

So this seems to use the TEMP env var or similar to get to the temp folder, so we could pass in the folder.

Or again maybe for the test runs on Windows I could just add the temp folder to the policy with write access, assuming we have a safe way of indicating to the C++ code when we are running tests??

That would fix things for the leak log as well.
Even if that's just a short term thing.

Comment 10

[Bob Owen (:bobowen)]

There are some try pushes with a patch for the leak log as well in bug 1219369 comment 14.

Comment 11

[Bob Owen (:bobowen)]

Attachment: Log to the process log when launching a sandboxed process on Windows

While simple this is not ideal as we're calling GetProcId twice.
I don't want to do this in the sandboxbroker dll as that involves including ipc headers, which might lead to problems.

I think it would be good if the LaunchApp()s were changed to return the ProcessID as well and we just did this logging in GeckoChildProcessHost.
That would fix it for Mac as well although it looks like we need to fix other issues to do this from bug 950401.
We do write to this log for an extra reason in process_util_linux.cc, but I'm not sure how often that happens or whether it is needed.

Comment 12

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Comment on attachment 8715206 [details] [diff] [review]
Log to the process log when launching a sandboxed process on Windows

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

I'd definitely be in favor of centralizing this logging. It sounds like the issues in bug 950401 have been fixed. I doubt we need to worry about the extra chdir log line for linux (if that's what you're referring to). But let's get this fixed first.

Comment 13

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/bd5d1c3f3c1e

Comment 14

[Carsten Book [:Tomcat]]

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