764442 - Application disconnect errors because of invalid frame objects if a test file restarts the browser

Status: RESOLVED FIXED

(Testing Graveyard :: Mozmill, defect)

Description

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

I can see those failures now on at least OS X and Windows. AFAIK it has been started today. Not sure why. Checking out an older changeset from Mozmill master doesn't change anything.

The command I run is:

mozmill -b /Applications/Firefox/Nightly.app/ -m mutt/mutt/tests/js/frame/tests.ini

Whenever the third persisted test has been finished we quit with:

TEST-PASS | persisted.js | testThree
TEST-UNEXPECTED-FAIL | Disconnect Error: Application unexpectedly closed
RESULTS | Passed: 5
RESULTS | Failed: 0
RESULTS | Skipped: 0
ERROR | Traceback (most recent call last):
ERROR |   File "/Volumes/data/code/tools/mozmill/mozmill/mozmill/__init__.py", line 664, in run
ERROR |     mozmill.run(*tests)
ERROR |   File "/Volumes/data/code/tools/mozmill/mozmill/mozmill/__init__.py", line 365, in run
ERROR |     self.run_tests(*tests)
ERROR |   File "/Volumes/data/code/tools/mozmill/mozmill/mozmill/__init__.py", line 334, in run_tests
ERROR |     self.run_test_file(frame, test['path'])
ERROR |   File "/Volumes/data/code/tools/mozmill/mozmill/mozmill/__init__.py", line 292, in run_test_file
ERROR |     frame.runTestFile(path, False, name)
ERROR |   File "/Volumes/data/code/tools/mozmill/jsbridge/jsbridge/jsobjects.py", line 68, in __getattr__
ERROR |     if name in self.__attributes__():
ERROR |   File "/Volumes/data/code/tools/mozmill/jsbridge/jsbridge/jsobjects.py", line 54, in __attributes__
ERROR |     return self._bridge_.describe(self._name_)['attributes']
ERROR |   File "/Volumes/data/code/tools/mozmill/jsbridge/jsbridge/network.py", line 197, in describe
ERROR |     return self.run(_uuid, 'bridge.describe('+', '.join([encoder.encode(_uuid), obj_name])+')')
ERROR |   File "/Volumes/data/code/tools/mozmill/jsbridge/jsbridge/network.py", line 154, in run
ERROR |     self.send(exec_string)
ERROR |   File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/asyncore.py", line 365, in send
ERROR |     result = self.socket.send(data)
ERROR |   File "/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/socket.py", line 170, in _dummy
ERROR |     raise error(EBADF, 'Bad file descriptor')
ERROR | error: [Errno 9] Bad file descriptor


This blocks me from finishing the jsbridge patch on bug 686320.

Comment 1

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

Here with the logging enabled:

EST-PASS | persisted.js | testThree
INFO | 
INFO | * Fire event: 'mozmill.persist'
INFO | 
INFO | * Fire event: 'mozmill.endRunner'
INFO | 
INFO | * Set: 'a811b147-b58b-11e1-9769-109add6a95a5'
INFO | 
INFO | * Describe: 'a838064a-b58b-11e1-a8a2-109add6a95a5, true'
INFO | 
INFO | [Errno 9] Bad file descriptor
INFO | 
INFO | String: bridge.describe("a856c6c0-b58b-11e1-b05a-109add6a95a5", bridge.registry["{f5e67d18-60db-814d-9e8b-6f9411af6de8}"])
INFO | 
INFO | * Set: 'a90e3a63-b58b-11e1-a4ee-109add6a95a5'
INFO | 
INFO | * Describe: 'a92ce111-b58b-11e1-9e13-109add6a95a5, [object BackstagePass]'
INFO | 
INFO | * Describe: 'a94b7147-b58b-11e1-a669-109add6a95a5, function cleanQuit() {
INFO | 
INFO |     var quitmethod = utils.getMethodInWindows("goQuitApplication");
INFO | 
INFO |     var settimeoutmethod = utils.getMethodInWindows("setTimeout");
INFO | 
INFO |     settimeoutmethod(quitmethod, 50);
INFO | 
INFO | }'
INFO | 
INFO | * Exec function: 'a96a2be3-b58b-11e1-930b-109add6a95a5 (cleanQuit)'
INFO | 
INFO | * Observer topic: 'quit-application'
INFO | 
INFO | * Fire event: 'mozmill.fail'
INFO | 

So we are sending an uuid which doesn't seem to exist?

bridge.describe("a856c6c0-b58b-11e1-b05a-109add6a95a5", bridge.registry["{f5e67d18-60db-814d-9e8b-6f9411af6de8}"])

Comment 2

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

So this is actually related to the restartApplication() method in MozMillController. If you change that to an user restart it works fine. For now I have assembled a simplified testcase which I will attach in a bit.

Comment 3

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

Here the link to the branch which I use to get this fixed:
https://github.com/whimboo/mozmill/compare/disconnect

Patch:
https://github.com/whimboo/mozmill/compare/disconnect.patch

Comment 4

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

So that feature came in with bug 638989. Jeff, I hope you can have at least a look at. Hopefully you can see something important here, which could help me to fix this disconnect.

Comment 5

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

So we are failing when we want to call:

  frame.runTestFile(path, False, name)

See:
https://github.com/mozautomation/mozmill/blob/master/mozmill/mozmill/__init__.py#L292

Comment 6

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

That's kinda interesting:

INFO | frame
INFO | 
INFO | <jsbridge.jsobjects.JSObject object at 0x104213e50>
INFO | 
TEST-START | test_pre.js | setupTest
TEST-START | test_pre.js | testOne
TEST-PASS | test_pre.js | testOne
INFO | *********** quit application
INFO | 
INFO | frame
INFO | 
INFO | <jsbridge.jsobjects.JSObject object at 0x104213c10>
INFO | 
TEST-START | test_pre.js | setupTest
TEST-START | test_pre.js | testTwo
TEST-PASS | test_pre.js | testTwo
INFO | frame
INFO | 
INFO | <jsbridge.jsobjects.JSObject object at 0x104213e50>
INFO | 
TEST-UNEXPECTED-FAIL | Disconnect Error: Application unexpectedly closed


We instantiate a frame object at the beginning of the test run which then gets changed after the first restart via restartApplication(). Surprisingly for test_post we again have the original frame object, which shouldn't exist anymore.

Comment 7

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

Ok, now it's clear what's going on here. In run_test_file() we call 'frame = self.start_runner()' again if there is another test function in the same module. This new frame never gets returned to 'run_tests', and Mozmill will use the old frame again for the next test module.

Can we have the frame as property on the Mozmill class? I would highly be in favor of this! Otherwise it's getting complicated by passing the frame around as function parameter.

Comment 8

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

Attachment: Patch

Pointer to Github pull-request

Comment 9

[Jeff Hammel]

Ah, I see. Thanks for tracking it down, Henrik.  I think your fix in http://pastebin.mozilla.org/1662043 will suffice.  I'm not against taking frame on the mozmill instance *iff* we make sure to clean if up correctly.  This may be easy, but a mistake can cause the instance to get in a bad state in the same class of problems as this bug :(

Comment 10

[Jeff Hammel]

Comment on attachment 632911 [details]
Patch

Yep, looks good.  I'm ashamed I didn't notice this before

Comment 11

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

Pushed:
https://github.com/mozautomation/mozmill/commit/03ebba891773533316beadc888f5395bae2fa59b

Ok, lets leave it that way for now. If we feel later that it would be fine to have it as class property we can do it then.

Comment 12

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

This is not solved yet. Please check line 302 of __init__.py:
https://github.com/mozautomation/mozmill/commit/03ebba891773533316beadc888f5395bae2fa59b#L0L301

This method is recursive and we loose the newly created frame from the sub invocation of the method. :/

Comment 13

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

Attachment: Part II

Pointer to Github pull-request

Comment 14

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

Comment on attachment 635221 [details]
Part II

With this patch we also take care of multiple restarts within a single test file. It should fix all the remaining problems I have seen yesterday.

Comment 15

[Jeff Hammel]

Comment on attachment 635221 [details]
Part II

Looks good to me

Comment 16

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

Part II landed as:
https://github.com/mozautomation/mozmill/commit/55731c3d749687f0276bf4e0672f274ef05d70f3