640435 - 'this.server is undefined' when running user restart test

Status: RESOLVED FIXED

(Testing Graveyard :: Mozmill, defect)

Description

[Andrew Halberstadt [:ahal]]

STR:
mozmill -t mozmill/test/restart/test_user_restart/ --restart --show-all

Results:
The first test (test1.js) gets run and passes normally. The browser gets restarted on the javascript side but then the setupModule in test2.js never gets run.

The application hangs for a bit before being killed by timeout
Timeout: bridge.set("619f272a-4ab8-11e0-bc0e-f0def13a77e5", Components.utils.import('resource://mozmill/modules/frame.js'))

In the error console I see:
Error: this.server is undefined
Source File: resource://jsbridge/modules/nspr-server.js
Line: 116

**Notes:
* Only reproducible in Minefield
* test3.js test4.js and test5.js are SUPPOSED to fail, so don't be surprised if you see this

Comment 1

[Heather Arthur [:harth]]

I got this in the dump:

jsbridge: Exception: socket failed to bind, kill all firefox processes

There was an exception when it tried to bind to that port, the port must still be in use by the first Firefox process.

Comment 2

[Andrew Halberstadt [:ahal]]

Hmm this might be a bit of a fundamental problem with regards to user restart.

You have to keep in mind that the browser is getting restarted via a restart button. When you restart the browser this way it uses the same process (to see what I mean start Firefox from the command line, and type window.Application.restart(); into the error console).

Comment 3

[Jeff Hammel]

So, it is worse even that that.  Since you don't have a working JS bridge, the application won't be closed at all, giving an indefinite hang.  

This can/should be solved by fixing JS bridge and user restart to close the bridge/server before restarting.

Comment 4

[Heather Arthur [:harth]]

what is the status of this given that bug 638989 (restart tests) has landed?

Comment 5

[Jeff Hammel]

The bugs are unrelated.  In short the harness triggered restarts (added by bug 638989) work properly (in FF4) as can be seen by running test_runnershutdown.js.  User shutdowns (test_usershutdown.js) formerly did not work for me either either before or after landing bug 638989.  Now, on this computer (not the one I was previously using) I cannot reproduce on casual inspection though abict nothing has changed mozmill-side.  I'll try other repro steps as time permits.  Maybe changes to nightlies have "fixed" the issue? ::shrug:: Can anyone else run test_usershutdown.js and get the error, preferably in the middle of other tests?

Comment 6

[Andrew Halberstadt [:ahal]]

I think it was the restart tests that were failing (i.e test/restart/test_user_restart/test1.js etc.)

But yeah, it should be un-related to bug 638989 as Jeff mentioned.

Comment 7

[Heather Arthur [:harth]]

hmm, still getting this error message with test_user_restart.js. Unfortunately it doesn't get dumped either because it's in jsbridge land, you have to check the error console manually.

Comment 8

[Heather Arthur [:harth]]

Alright, I tried polling on PR_Bind for two minutes and it didn't work, so it doesn't seem to be a race condition.

Comment 9

[Heather Arthur [:harth]]

Officially getting a PR_SOCKET_ADDRESS_IS_BOUND_ERROR error after some nspr probing.

I don't know a lot about sockets, but do we have to un-bind? or close or something?

Comment 10

[cmtalbert]

Are we using Reuseaddr option on the socket?  That might help us in this case.

See: http://mxr.mozilla.org/mozilla-central/ident?i=PR_SockOpt_Reuseaddr

Comment 11

[Heather Arthur [:harth]]

(In reply to comment #10)
> Are we using Reuseaddr option on the socket?  That might help us in this
> case.
> 
> See: http://mxr.mozilla.org/mozilla-central/ident?i=PR_SockOpt_Reuseaddr

Yeah, we set that.

Comment 12

[Jeff Hammel]

So logging on master:

DEBUG | mozmill.startRunner | true
DEBUG | mozmill.setModule | "currentModule"
DEBUG | mozmill.setState | "currentState"
TEST-START | mutt/mutt/tests/js/restart/test_user_restart/test1.js | setupModule
DEBUG | mozmill.setTest | {"name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill/mutt/mutt/tests/js/restart/test_user_restart/test1.js"}
DEBUG | mozmill.setState | "currentState"
TEST-START | mutt/mutt/tests/js/restart/test_user_restart/test1.js | testRestartBeforeTimeout
DEBUG | mozmill.setTest | {"name": "testRestartBeforeTimeout", "filename": "/home/jhammel/mozmill/src/mozmill/mutt/mutt/tests/js/restart/test_user_restart/test1.js"}
DEBUG | mozmill.userShutdown | {"resetProfile": false, "user": true, "restart": true}
TEST-PASS | mutt/mutt/tests/js/restart/test_user_restart/test1.js | testRestartBeforeTimeout
DEBUG | mozmill.endTest | {"passes": [], "fails": [], "time_start": 1311791115957, "name": "testRestartBeforeTimeout", "time_end": 1311791117508, "filename": "/home/jhammel/mozmill/src/mozmill/mutt/mutt/tests/js/restart/test_user_restart/test1.js", "failed": 0, "passed": 0}
DEBUG | mozmill.persist | {}
DEBUG | mozmill.endRunner | true
ERROR | Test Failure: {"message": "[JavaScript Error: \"[Exception... \"Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]\"  nsresult: \"0x80004005 (NS_ERROR_FAILURE)\"  location: \"JS frame :: resource:///components/fuelApplication.js :: app_observe :: line 1321\"  data: no]\" {file: \"resource:///components/fuelApplication.js\" line: 1321}]"}
INFO | Timeout: bridge.describe("c76237e0-b87d-11e0-9022-00262df16844", bridge.registry["{a6c2c3a2-7d53-4595-b173-5dd24ba05992}"])
INFO | 
INFO | Timeout: bridge.set("ebbcc6c8-b87d-11e0-9022-00262df16844", Components.utils.import('resource://mozmill/modules/frame.js'))
INFO | 
INFO | Timeout: bridge.set("ec27fa1a-b87d-11e0-9022-00262df16844", Components.utils.import('resource://mozmill/modules/frame.js'))
INFO | 
INFO | Timeout: bridge.set("ec93342e-b87d-11e0-9022-00262df16844", Components.utils.import('resource://mozmill/modules/frame.js'))
INFO | 
INFO | Timeout: bridge.set("ecfe6618-b87d-11e0-9022-00262df16844", Components.utils.import('resource://mozmill/modules/frame.js'))
INFO | 
INFO | Passed: 1
INFO | Failed: 0
INFO | Skipped: 0

Looking at the code:

var Server = function(port) {
  try {
    this.server = new socket.ServerSocket(port);
  } catch(e) {
    log('jsbridge: Exception: ' + e);
  }
}

Server.prototype.start = function () {
  this.server.onConnect(function(client) {
    sessions.add(new Session(client));
  });
}

It fails on the `this.server.onConnect` line. ABICT, this should only happen if the `try-catch` in the ctor is triggered.  We, probably stupidly, ignore this error and log it.  However, the log function doesn't ever print to console even for --console-level=DEBUG . This is not good.  We should probably not catch this error, or otherwise do something more intelligent

Comment 13

[Jeff Hammel]

Removing the try-catch, the actual error is 

Error: [Exception... "'socket failed to bind, kill all firefox processes' when calling method: [nsICommandLineHandler::handle]"  nsresult: "0x8057001e (NS_ERROR_XPC_JS_THREW_STRING)"  location: "<unknown>"  data: no]

Comment 14

[Jeff Hammel]

So I have something working. 

https://github.com/k0s/mozmill/tree/bug-640435

Indeed, if you actually shutdown the server at quit-application, things work.
I'll undo my mad scientist experimentation and get a patch up.

Also, this exposed another bug : user restart tests are not reported correctly.  This is in fact another bug, but since they were broken no one noticed ;)  Run restart/test_user_restart/test1.js by itself.  0 failures, 0 passes, 0 skipped.  Should be 1 pass.  Not sure if I'll fix this here or follow up, but important not to forget.

Comment 15

[Jeff Hammel]

I have played with this a bit and can't this to work both as an nsIObserver and a command line handler.  It's probably my lack of understanding of XPCOM.  On the plus side, the fix using nsIObserver seems pretty solid.  I'll poke around a little more, and if I continue to be stuck I'll post what I have to this bug.

Comment 16

[Jeff Hammel]

(In reply to comment #9)
> Officially getting a PR_SOCKET_ADDRESS_IS_BOUND_ERROR error after some nspr
> probing.
> 
> I don't know a lot about sockets, but do we have to un-bind? or close or
> something?

To clear up this mystery a little, the short answer is "evidently".  All we really know is that this worked up until a few months before Fx shipped (sometime in 2011, maybe ahal remembers better?).  So something (or several somethings) happened to how sockets and/or nsICommandLineHandler was changed on restart.  ABICT, the socket (now) remains open, but it isn't connected to anything in JS-land. The restarted socket bind never happens.  In effect, this means we now have to close it down.

I am currently unsure why exactly this happens. I have successfully worked around this by using events from nsIObserver to open and close. Maybe more will be clear when I have the nsICommandLineHandler parts in place.

Comment 17

[Jeff Hammel]

Attachment: example cmdargs.js

WIP of jsbridge cmdargs.js component; the observer portion works, but i can't figure out the port :

Contract ID '@mozilla.org/commandlinehandler/general-startup;1?type=jsbridge' was registered as a command line handler for entry 'jsbridge', but could not be created.

The chrome.manifest::

resource jsbridge resource/

content jsbridge chrome/content/

overlay chrome://browser/content/browser.xul chrome://jsbridge/content/overlay.xul
overlay chrome://messenger/content/mailWindowOverlay.xul chrome://jsbridge/content/overlay.xul

overlay chrome://calendar/content/calendar.xul chrome://jsbridge/content/overlay.xul

overlay windowtype:Songbird:Main chrome://jsbridge/content/overlay.xul

component {2872d428-14f6-11de-ac86-001f5bd9235c} components/cmdarg.js
contract @mozilla.org/commandlinehandler/general-startup;1?type=jsbridge {2872d428-14f6-11de-ac86-001f5bd9235c}
category profile-after-change jsbridge @mozilla.org/commandlinehandler/general-startup;1?type=jsbridge
category command-line-handler jsbridge @mozilla.org/commandlinehandler/general-startup;1?type=jsbridge

Comment 18

[Jeff Hammel]

So I got the command line handler wired in with some XPCOM black magic I don't really understand.

Discovery #1: we were never handling the JS port correctly for user restart.  Look at this log with comments in situ:

---profile-after-change---
I'm observing this init function
---handling command line---
[xpconnect wrapped nsICommandLine]
: -silent
: -foreground
port: null
i is in your box startine ur serverz 24242

This is the dummy run to register extensions: https://github.com/mozautomation/mozmill/blob/master/mozrunner/mozrunner/runner.py#L223 ; quit-application and server shutdown is not done.  Strangely, this doesn't cause issues.

---profile-after-change---
I'm observing this init function
---handling command line---
[xpconnect wrapped nsICommandLine]
: -jsbridge
: 24242
: -foreground
port: 24242
i is in your box startine ur serverz 24242
---quit-application---
I'm not observing this anymore
We're done with this one

This is the normal run.  Everything is fine and dandy.  We parse the port and serve with it and stop on shutdown.

---profile-after-change---
I'm observing this init function
---handling command line---
[xpconnect wrapped nsICommandLine]
port: null
i is in your box startine ur serverz 24242
---quit-application---
I'm not observing this anymore
We're done with this one

This is the subsequent run after user-restart.  We start the server and shutdown cleanly.  However, port does not show up in the command line args!
We don't currently ever notice this since the port we use is always the default, port 24242, but this is a bug.  If we ever did vary the port on the mozmill side and ran a user restart test, this would fail.

I'm not entirely sure how to get around this issue.

Comment 19

[Jeff Hammel]

Attachment: WIP

So this patch should actually solve the issues.  Strangely, a few things that need to be fixed:

* test1.js does not report results; no pass, no fail, no skip; should be 1 pass

* running test1.js twice in a row (e.g. -t test2.js -t test2.js) gives a skip on the second test.  The browser is *not* shutdown between tests

Neither of them are caused by this bug.  It would be nice to cleanup with this bug so that user restart tests actually work, but could also reticket

Comment 20

[Jeff Hammel]

Attachment: final patch, i hope

This has actually exposed a number of other issues I'll ticket subsequently, but after careful inspection they don't seem to be the fault of this patch.  This fixes user restart, but not user shutdown.  Clint's and my computers fail in different ways, so its a bit of a nest to decipher.  I'll ticket these and post their #s back to this bug.

Also, there seems to be an upstream bug(?) wrt command line arguments when the application restarts.  I'll ticket that too

Comment 21

[Jeff Hammel]

Also, I mistakenly bumped to ManifestDestiny version 0.5.3 in the bug.  This is, um, buggy.  I will bump to 0.5.4 in the final patch (can upload on request).

Comment 22

[Jeff Hammel]

I made a manifest of two passing user restart tests:

# test user restart

[test1.js]
[test1.js]
[test1.js]
[test2.js]
[test2.js]

Here is what I get:

(mozmill)│mozmill -m mutt/mutt/tests/js/restart/test_user_restart/manifest.ini 
Xlib:  extension "GLX" missing on display ":0.0".
TEST-START | test1.js | setupModule
TEST-START | test1.js | testRestartBeforeTimeout
TEST-START | test1.js | setupModule
TEST-START | test1.js | testRestartBeforeTimeout
TEST-START | test1.js | setupModule
TEST-START | test1.js | testRestartBeforeTimeout
TEST-START | test2.js | setupModule
TEST-START | test2.js | testShutdownBeforeTimeout
TEST-PASS | test2.js | testShutdownBeforeTimeout
TEST-START | test2.js | setupModule
ERROR | Test Failure: {"function": "Runner.wrapper", "message": "Shutdown expected but none detected before end of test", "userShutdown": {"resetProfile": false, "user": true, "restart": false}}
TEST-START | test2.js | testShutdownBeforeTimeout
INFO | Test Skipped: "setupModule failed."
WARNING | testShutdownBeforeTimeout | (SKIP) setupModule failed.
INFO | Passed: 1
INFO | Failed: 0
INFO | Skipped: 1

Notice...there are a few things wrong here ;)

- test1.js is not counted as part of the results.  This is bad.
- the browser does not shut down between test2.js and the subsequent test2.js.  This is also bad.

Not sure what is going on here :(

Comment 23

[Jeff Hammel]

Similarly:

(mozmill)│mozmill -t mutt/mutt/tests/js/restart/test_user_restart/test2.js -t mutt/mutt/tests/js/restart/test_user_restart/test2.js
Xlib:  extension "GLX" missing on display ":0.0".
TEST-START | mutt/mutt/tests/js/restart/test_user_restart/test2.js | setupModule
TEST-START | mutt/mutt/tests/js/restart/test_user_restart/test2.js | testShutdownBeforeTimeout
TEST-PASS | mutt/mutt/tests/js/restart/test_user_restart/test2.js | testShutdownBeforeTimeout
TEST-START | mutt/mutt/tests/js/restart/test_user_restart/test2.js | setupModule
ERROR | Test Failure: {"function": "Runner.wrapper", "message": "Shutdown expected but none detected before end of test", "userShutdown": {"resetProfile": false, "user": true, "restart": false}}
TEST-START | mutt/mutt/tests/js/restart/test_user_restart/test2.js | testShutdownBeforeTimeout
INFO | Test Skipped: "setupModule failed."
WARNING | testShutdownBeforeTimeout | (SKIP) setupModule failed.
INFO | Passed: 1
INFO | Failed: 0
INFO | Skipped: 1

I do not get a restart between tests :(

Comment 24

[Jeff Hammel]

The big problem looks like a test problem:

https://github.com/mozautomation/mozmill/blob/master/mutt/mutt/tests/js/restart/test_user_restart/test2.js#L10

While this is obscured running after the line `controller.startUserShutdown`, removing this line gives the error:

ERROR | Test Failure: {"exception": {"stack": "()@resource://mozmill/modules/controller.js:406\n()@resource://mozmill/modules/frame.js -> file:///home/jhammel/mozmill/src/mozmill/mutt/mutt/tests/js/restart/test_user_restart/test2.js:11\n((function () {controller.click(new elementslib.Elem(controller.menus['file-menu'].menu_FileQuitItem));}))@resource://mozmill/modules/frame.js:499\n([object Object])@resource://mozmill/modules/frame.js:553\n(\"/home/jhammel/mozmill/src/mozmill/mutt/mutt/tests/js/restart/test_user_restart/test2.js\",null)@resource://mozmill/modules/frame.js:463\n(\"/home/jhammel/mozmill/src/mozmill/mutt/mutt/tests/js/restart/test_user_restart/test2.js\",false,null)@resource://mozmill/modules/frame.js:588\n((function (filename, invokedFromIDE, name) {var runner = new Runner(new Collector, invokedFromIDE);runner.runTestFile(filename, name);runner.end();return true;}),[object Proxy])@resource://jsbridge/modules/bridge.js:135\n(\"59e9da12-bc86-11e0-8eb7-00262df16844\",(function (filename, invokedFromIDE, name) {var runner = new Runner(new Collector, invokedFromIDE);runner.runTestFile(filename, name);runner.end();return true;}),[object Proxy])@resource://jsbridge/modules/bridge.js:139\n", "message": "MenuTree is not defined", "fileName": "resource://mozmill/modules/controller.js", "name": "ReferenceError", "lineNumber": 406}}
TEST-UNEXPECTED-FAIL | mutt/mutt/tests/js/restart/test_user_restart/test2.js | testShutdownBeforeTimeout
ERROR | Test Failure: {"message": "[JavaScript Error: \"MenuTree is not defined\" {file: \"resource://mozmill/modules/controller.js\" line: 406}]"}

Can anyone give much enlightenment on this?

Comment 25

[Jeff Hammel]

Attachment: patch to make test2 work

This will make test2 actually work like it is supposed to

Comment 26

[Jeff Hammel]

wrt comment 18 , I filed bug 675785 and bug 675787. Should be fixed, but not in this bug, and it has an upstream dep (toolkit)

Comment 27

[Jeff Hammel]

Attachment: even more fixed

includes some other fixes.  Reporting is still not good, but better than the current case which is just not reported at all

Comment 28

[cmtalbert]

Comment on attachment 549980 [details] [diff] [review]
even more fixed

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

r+, this looks good.  This bug opened a can of worms.  But I think you've dealt with it quite well. One question about the manifest parser changes - were they necessary in order to have a bunch of tests with the same name in a manifest?

::: jsbridge/jsbridge/extension/components/cmdarg.js
@@ +80,3 @@
>    // follow the guidelines in nsICommandLineHandler.idl
>    // specifically, flag descriptions should start at
>    // character 24, and lines should be wrapped at

nit: This comment looks incomplete and doesn't add anything, I'd remove it.

Comment 29

[Jeff Hammel]

(In reply to comment #28)
> Comment on attachment 549980 [details] [diff] [review] [diff] [details] [review]
> even more fixed
> 
> Review of attachment 549980 [details] [diff] [review] [diff] [details] [review]:
> -----------------------------------------------------------------
> 
> r+, this looks good.  This bug opened a can of worms.  But I think you've
> dealt with it quite well. One question about the manifest parser changes -
> were they necessary in order to have a bunch of tests with the same name in
> a manifest?
> 

The old manifest parser, or at least the way I was using it, did not support multiple of the same test.  The newer one, 0.5.3, had a bug, so I fixed it and pegged to 0.5.4 across the board.  Probably overkill but that's how we do all of our internal dependencies, currently.

> ::: jsbridge/jsbridge/extension/components/cmdarg.js
> @@ +80,3 @@
> >    // follow the guidelines in nsICommandLineHandler.idl
> >    // specifically, flag descriptions should start at
> >    // character 24, and lines should be wrapped at
> 
> nit: This comment looks incomplete and doesn't add anything, I'd remove it.

This was in the original code.  I only removed the "CHANGE THIS BOILERPLATE" line.  For one, I would like to keep this code, as otherwise I would forget why the string is in the silly format that it is

Comment 30

[Jeff Hammel]

pushed to master: https://github.com/mozautomation/mozmill/commit/06c437895c9ce7cc82f0b4b708801b66a96b518e