753273 - wait_for_port (it's copy to be more exact) returns false positive on Nightly @ win32

Status: RESOLVED WORKSFORME

(Remote Protocol :: Marionette, defect)

Description

[Andrzej Skalski]

I am writing MATS (https://wiki.mozilla.org/Accessibility/MATS, page is outdated), and I use MozRunner to run Firefox. After I start MozRunner in separate thread (it blocks) I wait in main thread for Firefox to open Marionette's port. As :jgryffin suggested, to do that I use a copy of following procedure: 
https://github.com/mozilla/marionette_client/blob/master/marionette/emulator.py#L246 with desktop Nightly on Windows XP (that's the first environment I need MATS to get working with).

Just after method returns "True", I create Marionette object (from Marionette Client library from mozilla-central) and do:
m = Marionette('localhost', self.marionette_port) #tried with 127.0.0.1 as well
m.start_session()

I get following error:

{u'message': u"error occurred while processing 'newSession' request: TypeError: this.browser is undefined", u'from': u'conn1.marionette1', u'error': u'unknownError'}

the 'data' object from lines 253 and 255 of mentioned method, equals to:

<code>
66:{
  "from": "
</code>

(it contains twice \n and probably \t, I got it viewed using standard print, not debugger :( )

when I add

sleep(4)
between wait_for_port and m.start_session(), I get:

invalid literal for int() with base 10: ''

but the session at least starts, so it's a progress, and I will be back to that later.

Anyway, unless I do something wrong, wait_for_port function is not reliable on win32, and it uses "active waiting", which is not the safest way to code, right? Maybe Marionette should signal it's readiness in some other way than by just opening the port?

Comment 1

[Andrzej Skalski]

btw, I meant "jgriffin" not "jgryffin", sorry for that.

Comment 2

[Andrzej Skalski]

btw, I just got this *with* sleep(4):

{u'message': u"error occurred while processing 'newSession' request: TypeError: win is null", u'from': u'conn1.marionette1', u'error': u'unknownError'}

trace:

--DOCSHELL 0660BCB0 == 3 [id = 1]
MATS: error ***"Traceback (most recent call last):
  File "E:\mats\mats_runner\mats_runner.py", line 38, in __init__
    m.start_session()
  File "E:\mozbase-win32\lib\site-packages\marionette-0.2-py2.7.egg\marionette\marionette.py", line 209, in start_session
    self.session = self._send_message('newSession', 'value')
  File "E:\mozbase-win32\lib\site-packages\marionette-0.2-py2.7.egg\marionette\marionette.py", line 170, in _send_message
    self._handle_error(response)
  File "E:\mozbase-win32\lib\site-packages\marionette-0.2-py2.7.egg\marionette\marionette.py", line 199, in _handle_error
    raise MarionetteException(message=response, status=500)
MarionetteException: {u'message': u"error occurred while processing 'newSession' request: TypeError: win is null", u'from': u'conn1.marionette1', u'error': u'unknownError'}

Comment 3

[Andrzej Skalski]

and without sleep(4) on Linux:

{u'message': u"error occurred while processing 'newSession' request: ReferenceError: goSetCommandEnabled is not defined", u'from': u'conn1.marionette1', u'error': u'unknownError'}

traceback:

Traceback (most recent call last):
  File "/home/akuda/Moz/mats/mats_runner/mats_runner.py", line 38, in __init__
    m.start_session()
  File "/home/akuda/Moz/mozbase-lin/local/lib/python2.7/site-packages/marionette-0.2-py2.7.egg/marionette/marionette.py", line 209, in start_session
    self.session = self._send_message('newSession', 'value')
  File "/home/akuda/Moz/mozbase-lin/local/lib/python2.7/site-packages/marionette-0.2-py2.7.egg/marionette/marionette.py", line 170, in _send_message
    self._handle_error(response)
  File "/home/akuda/Moz/mozbase-lin/local/lib/python2.7/site-packages/marionette-0.2-py2.7.egg/marionette/marionette.py", line 199, in _handle_error
    raise MarionetteException(message=response, status=500)
MarionetteException: {u'message': u"error occurred while processing 'newSession' request: ReferenceError: goSetCommandEnabled is not defined", u'from': u'conn1.marionette1', u'error': u'unknownError'}

on linux, with sleep(4) it seems to work (navigates correctly to some webpages)

Comment 4

[Andrzej Skalski]

After adding "marionette.defaultPrefs.port": 2828 to profile prefs, I get:

ON LINUX:

Traceback (most recent call last):
  File "/home/akuda/Moz/mats/mats_runner/mats_runner.py", line 38, in __init__
    m.start_session()
  File "/home/akuda/Moz/mozbase-lin/local/lib/python2.7/site-packages/marionette-0.2-py2.7.egg/marionette/marionette.py", line 209, in start_session
    self.session = self._send_message('newSession', 'value')
  File "/home/akuda/Moz/mozbase-lin/local/lib/python2.7/site-packages/marionette-0.2-py2.7.egg/marionette/marionette.py", line 170, in _send_message
    self._handle_error(response)
  File "/home/akuda/Moz/mozbase-lin/local/lib/python2.7/site-packages/marionette-0.2-py2.7.egg/marionette/marionette.py", line 199, in _handle_error
    raise MarionetteException(message=response, status=500)
MarionetteException: {u'message': u"error occurred while processing 'newSession' request: TypeError: this.browser is null", u'from': u'conn1.marionette1', u'error': u'unknownError'}

ON WINDOWS XP:

Traceback (most recent call last):
  File "E:\mats\mats_runner\mats_runner.py", line 38, in __init__
    m.start_session()
  File "E:\mozbase-win32\lib\site-packages\marionette-0.2-py2.7.egg\marionette\marionette.py", line 209, in start_session
    self.session = self._send_message('newSession', 'value')
  File "E:\mozbase-win32\lib\site-packages\marionette-0.2-py2.7.egg\marionette\marionette.py", line 170, in _send_message
    self._handle_error(response)
  File "E:\mozbase-win32\lib\site-packages\marionette-0.2-py2.7.egg\marionette\marionette.py", line 199, in _handle_error
    raise MarionetteException(message=response, status=500)
MarionetteException: {u'message': u"error occurred while processing 'newSession' request: TypeError: this.browser is undefined", u'from': u'conn1.marionette1', u'error': u'unknownError'}

Comment 5

[Andrzej Skalski]

(both without sleep(4) )

Comment 6

[Jonathan Griffin (:jgriffin)]

Is the mats_runner.py anywhere that I could take a look at it?

Comment 7

[Jonathan Griffin (:jgriffin)]

Marionette opens its port very early in the app startup sequence, but the new_session command fails if a browser window isn't instantiated.  My guess is that you're connecting to Marionette before a browser window exists, and this is causing the errors.  Can you try adding a sleep(15) or so after the port is open, but before you call new session?

Comment 8

[David Burns :automatedtester]

Attachment: Simple code to replicate

I have managed to replicate this with a very simple bit of python

Comment 9

[Jonathan Griffin (:jgriffin)]

(In reply to Jonathan Griffin (:jgriffin) from comment #7)
> Marionette opens its port very early in the app startup sequence, but the
> new_session command fails if a browser window isn't instantiated.  My guess
> is that you're connecting to Marionette before a browser window exists, and
> this is causing the errors.  Can you try adding a sleep(15) or so after the
> port is open, but before you call new session?

Thanks for the example.  This is indeed what's happening.  We'll fix it so that new_session waits for a browser to become available before returning, but meanwhile a workaround is to call time.sleep(15) after wait_for_port returns.

Comment 10

[Jonathan Griffin (:jgriffin)]

Attachment: patch v0.1

Wait for a window and browser to exist at the start of newSession.

Comment 11

[Jonathan Griffin (:jgriffin)]

http://hg.mozilla.org/integration/mozilla-inbound/rev/49dd71fe75d7

Comment 12

[Joe Drew (not getting mail)]

https://hg.mozilla.org/mozilla-central/rev/49dd71fe75d7

Comment 13

[Andrzej Skalski]

Ok, so I thought it's resolved, updated mozilla-central, and now I have a different type of error. Win XP 32.

I have a following code:

            print 'connecting'
            m = Marionette('localhost', self.marionette_port)
            print 'starting session'
            m.start_session()
            print 'navigating'
            m.navigate('http://9gag.com/')
            print 'marionette succeeded'

The outcome is:

connecting
starting session
Traceback (most recent call last):
  File "E:\mats\mats_runner\mats_runner.py", line 42, in __init__
    m.start_session()
  File "E:\mozbase-win32\lib\site-packages\marionette-0.2-py2.7.egg\marionette\m
arionette.py", line 209, in start_session
    self.session = self._send_message('newSession', 'value')
  File "E:\mozbase-win32\lib\site-packages\marionette-0.2-py2.7.egg\marionette\m
arionette.py", line 165, in _send_message
    raise TimeoutException(message='socket.timeout', status=21, stacktrace=None)

TimeoutException: socket.timeout

What is important, is that the tab gets created, just function does not return.

And again, if I add

sleep(4) between wait_for_port() and Marionette constructor, everything works.

Comment 14

[Jonathan Griffin (:jgriffin)]

Seems to work ok now.