947248 - [mozprocess] Process.poll() doesn't account the i/o completion port handle and returns 0 even when the process hasn't fully stopped yet

Status: RESOLVED FIXED

(Testing :: Mozbase, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+1]]

As what I have seen on bug 944684 we return too early for an ended process. That means on WIndows the application can still have some handles to files open, which is causing "Access denied" errors or similar. As of now we retry to delete those files but that should not be the final solution given that other client code can also fail if it depends on the removal of those files.

Not sure where in detail the problem might be located in mozprocess but I think the handling of I/O completion ports could be related here.

A workaround would be to add a small sleep of 100ms after the self.proc.poll(), which in my case also fixed the problem. But that would be not that reliable given the different hardware specs. So a proper solution would be great to have.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

This is not only an issue on Windows. I'm seeing something similar on OS X for the kill() method. When it gets called via Mozrunner, it returns -9 as expected. But the process is still running and I cannot create a new jsbridge connection because the old one from the former process is still around. Doing a 'ps' for Firefox I can see a zombie process.

Comment 2

[William Lachance (:wlach)]

It probably makes sense to block on the managed process actually disappearing inside kill(). Note that there are some cases where a process can not be killed, in which case we should probably log/print some kind of warning before proceeding.

http://unix.stackexchange.com/questions/5642/what-if-kill-9-does-not-work

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Here the output from a testrun on OS X:

First start of Mozmill so a socket is available and we have a process with the pid 12799:

*** socket available ***
  501 12799 12793   0  4:09PM ttys000    0:00.57 /Applications/Firefox/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/wd/zmy4z7xn7wd7sjq90z1y52f80000gn/T/tmplfnjR_.mozrunner

Tests gets run and we kill the application via self.process_handler.kill() in mozrunner:

TEST-START | test1.js | setupModule
TEST-START | test1.js | testNewPageLoaded
Timeout: bridge.execFunction("41a1a023-882e-11e3-876e-109add6a95a5", bridge.registry["{063c6ce1-a697-a74d-b46a-26c685a4b018}"]["runTestFile"], ["/Volumes/data/code/mozmill/test/test1.js", null])

**** Lets kill the application...
Killed runner: -9

Right after we start the application again and accidentally detect that the socket is available. But it is for the old process which will be dead within a second and we fail in creating the bridge.

**** Restarting application after kill
*** socket available ***
  501 12799 12793   0  4:09PM ttys000    0:00.00 (firefox)
  501 12805 12793   0  4:10PM ttys000    0:00.00 /Applications/Firefox/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/wd/zmy4z7xn7wd7sjq90z1y52f80000gn/T/tmplfnjR_.mozrunner

TEST-UNEXPECTED-FAIL | Disconnect Error: Application unexpectedly closed

I will have a look at this bug in a bit.

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+1]]

So that's interesting. As talked on IRC with Andrew we usually use process groups on POSIX systems. I was able to get this fixed for killpg() but so far not for Popen.wait() which still returns too early. Not sure if that might actually be a platform bug. I'm able to workaround that by adding a small sleep of 1s as mentioned in my initial comment. I'm not sure why wait() in such a case returns immediately.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+1]]

I haven't analyzed all the process related code for Windows yet, but what I can say is that poll() returns 0 way too early while the process is not fully gone yet. Also the outThread is not active anymore, whereby I'm not sure if that one is in use on Windows. I will dive deeper into it.

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+1]]

So the solution here is easy. As of now we do not overload the poll() method in the Process class. That means when we call poll() on the process_handler, it will call poll() directly from the Popen class. But that class doesn't know anything about our i/o completion port stuff. So calling it will directly return 0, even when we still have an i/o handle.

What we have to do here is simply to overload the poll() method and check for the handle first. If that is not existent anymore, we can call Popen.poll() for the returncode. Otherwise we have to return None to indicate that the process has not been finished yet.

Patch upcoming soon. Not sure if a test will work given that all tests for mozprocess are disabled on Windows. But I will try.

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: Patch v1

Patch which fixes the problem. It's not fully tested yet. So I will do it now across platforms. I will also check which of our mozprocess tests we can re-enable now.

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: Patch v1.1

Updated patch given that I exported it on my Windows machine with an older version of mozbase, so that the line numbers were not in sync.

I have tested this and it works like a charm. No longer issues with access denied issues on Windows during our Mozmill tests.

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+1]]

I think that re-enabling the disabled tests on Windows we should do on the bug which has already been filed a while back.

Comment 10

[Andrew Halberstadt [:ahal]]

Comment on attachment 8375057 [details] [diff] [review]
Patch v1.1

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

Nice small change :)

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+1]]

https://github.com/mozilla/mozbase/commit/f9ae3301c2f95e9bd03bfb7f73d129ce96c37dcc

I will keep the in-testsuite flag set, so we can add tests later when they all are re-enabled for Windows.