davehunt/build.log

## build.log
Building on master Checkout:workspace / /Users/Shared/Jenkins/Home/jobs/mdn.staging/workspace - hudson.remoting.LocalChannel@6f76dd71 Using strategy: Default Last Built Revision: Revision 14384a8d45f03d4f76934cec602b3514cfcd9502 (origin/HEAD, origin/master) Checkout:workspace / /Users/Shared/Jenkins/Home/jobs/mdn.staging/workspace - hudson.remoting.LocalChannel@6f76dd71 Fetching changes from 1 remote Git repository Fetching upstream changes from git://github.com/mozilla/mdn-tests.git Seen branch in repository origin/HEAD Seen branch in repository origin/m Seen branch in repository origin/master Seen branch in repository origin/staging Commencing build of Revision 14384a8d45f03d4f76934cec602b3514cfcd9502 (origin/HEAD, origin/master) Checking out Revision 14384a8d45f03d4f76934cec602b3514cfcd9502 (origin/HEAD, origin/master) Warning : There are multiple branch changesets here [EnvInject] - Injecting as environment variables the properties content 'PATH=.env/bin:/usr/bin:/bin:/usr/sbin:/sbin' [workspace] $ /bin/sh -xe /var/folders/Wp/Wp49uNCTGAq9KGDuyHFZDU+++TI/-Tmp-/hudson1963919258291913138.sh + find results results.xml page.pyc -print0 + xargs -0 rm -v -Rf results/debug/test_dev_derby_TestDevDerbyPage_test_are_footer_links_visible.html results/debug/test_dev_derby_TestDevDerbyPage_test_are_footer_links_visible.png results/debug/test_dev_derby_TestDevDerbyPage_test_are_previous_challenges_present.html results/debug/test_dev_derby_TestDevDerbyPage_test_are_previous_challenges_present.png results/debug/test_dev_derby_TestDevDerbyPage_test_derby_links_visible.html results/debug/test_dev_derby_TestDevDerbyPage_test_derby_links_visible.png results/debug/test_dev_derby_TestDevDerbyPage_test_judge_images_visible.html results/debug/test_dev_derby_TestDevDerbyPage_test_judge_images_visible.png results/debug/test_homepage_TestHomepage_test_demo_image.html results/debug/test_homepage_TestHomepage_test_demo_image.png results/debug/test_homepage_TestHomepage_test_demo_title.html results/debug/test_homepage_TestHomepage_test_demo_title.png results/debug/test_homepage_TestHomepage_test_footer_links.html results/debug/test_homepage_TestHomepage_test_footer_links.png results/debug/test_homepage_TestHomepage_test_header_links.html results/debug/test_homepage_TestHomepage_test_header_links.png results/debug/test_learn_page_TestLearnPage_test_are_footer_links_visible.html results/debug/test_learn_page_TestLearnPage_test_are_footer_links_visible.png results/debug/test_learn_page_TestLearnPage_test_header_links_visible.html results/debug/test_learn_page_TestLearnPage_test_header_links_visible.png results/debug/test_learn_page_TestLearnPage_test_page_elements_are_visible.html results/debug/test_learn_page_TestLearnPage_test_page_elements_are_visible.png results/debug/test_login_TestLogin_test_login.html results/debug/test_login_TestLogin_test_login.png results/debug results/index.html results results.xml page.pyc [workspace] $ /bin/sh -xe /var/folders/Wp/Wp49uNCTGAq9KGDuyHFZDU+++TI/-Tmp-/hudson8089558012655075834.sh + '[' -d .env ']' + echo '**> virtualenv exists' **> virtualenv exists [workspace] $ /bin/sh -xe /var/folders/Wp/Wp49uNCTGAq9KGDuyHFZDU+++TI/-Tmp-/hudson780757454443661495.sh + pip install -Ur requirements/requirements.txt
Downloading/unpacking selenium (from -r requirements/requirements.txt (line 4)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fs%2Fselenium%2Fselenium-2.13.1.tar.gz Running setup.py egg_info for package selenium /System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/distutils/dist.py:266: UserWarning: Unknown distribution option: 'src_root' warnings.warn(msg) warning: no files found matching 'docs/api/py/index.rst' Downloading/unpacking pytest (from -r requirements/requirements.txt (line 5)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fp%2Fpytest%2Fpytest-2.2.0.zip Running setup.py egg_info for package pytest Downloading/unpacking pytest-xdist (from -r requirements/requirements.txt (line 6)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fp%2Fpytest-xdist%2Fpytest-xdist-1.7.zip Running setup.py egg_info for package pytest-xdist warning: no previously-included files found matching '*.orig' warning: no previously-included files found matching '*.rej' warning: no previously-included files matching '*.pyc' found under directory 'testing' warning: no previously-included files matching '*$py.class' found under directory 'testing' no previously-included directories found matching '.svn' no previously-included directories found matching '.hg' Downloading/unpacking unittestzero (from -r requirements/requirements.txt (line 7)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2FU%2FUnittestZero%2FUnittestZero-0.1.6.tar.gz Running setup.py egg_info for package unittestzero Downloading/unpacking pytest-mozwebqa (from -r requirements/requirements.txt (line 8)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fp%2Fpytest-mozwebqa%2Fpytest-mozwebqa-0.5.tar.gz Running setup.py egg_info for package pytest-mozwebqa Downloading/unpacking rdflib==3.1.0 (from selenium->-r requirements/requirements.txt (line 4)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fr%2Frdflib%2Frdflib-3.1.0.tar.gz Running setup.py egg_info for package rdflib Downloading/unpacking py>=1.4.5 (from pytest->-r requirements/requirements.txt (line 5)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fp%2Fpy%2Fpy-1.4.5.zip Running setup.py egg_info for package py Downloading/unpacking execnet>=1.0.8 (from pytest-xdist->-r requirements/requirements.txt (line 6)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fe%2Fexecnet%2Fexecnet-1.0.9.zip Running setup.py egg_info for package execnet no previously-included directories found matching 'doc/_build' warning: no previously-included files found matching '*.orig' warning: no previously-included files found matching '*.rej' warning: no previously-included files matching '*.pyc' found under directory 'execnet' warning: no previously-included files matching '*$py.class' found under directory 'execnet' warning: no previously-included files matching '*.pyc' found under directory 'testing' warning: no previously-included files matching '*$py.class' found under directory 'testing' no previously-included directories found matching '.svn' no previously-included directories found matching '.hg' Downloading/unpacking pyyaml (from pytest-mozwebqa->-r requirements/requirements.txt (line 8)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2FP%2FPyYAML%2FPyYAML-3.10.tar.gz Running setup.py egg_info for package pyyaml Installing collected packages: selenium, pytest, pytest-xdist, unittestzero, pytest-mozwebqa, rdflib, py, execnet, pyyaml Found existing installation: selenium 2.13.1 Uninstalling selenium: Successfully uninstalled selenium Running setup.py install for selenium /System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/distutils/dist.py:266: UserWarning: Unknown distribution option: 'src_root' warnings.warn(msg) warning: no files found matching 'docs/api/py/index.rst' Found existing installation: pytest 2.2.0 Uninstalling pytest: Successfully uninstalled pytest Running setup.py install for pytest Installing py.test script to /Users/Shared/Jenkins/Home/jobs/mdn.staging/workspace/.env/bin Installing py.test-2.6 script to /Users/Shared/Jenkins/Home/jobs/mdn.staging/workspace/.env/bin Found existing installation: pytest-xdist 1.7 Uninstalling pytest-xdist: Successfully uninstalled pytest-xdist Running setup.py install for pytest-xdist warning: no previously-included files found matching '*.orig' warning: no previously-included files found matching '*.rej' warning: no previously-included files matching '*.pyc' found under directory 'testing' warning: no previously-included files matching '*$py.class' found under directory 'testing' no previously-included directories found matching '.svn' no previously-included directories found matching '.hg' Found existing installation: UnittestZero 0.1.6 Uninstalling UnittestZero: Successfully uninstalled UnittestZero Running setup.py install for unittestzero Found existing installation: pytest-mozwebqa 0.5 Uninstalling pytest-mozwebqa: Successfully uninstalled pytest-mozwebqa Running setup.py install for pytest-mozwebqa Found existing installation: rdflib 3.1.0 Uninstalling rdflib: Successfully uninstalled rdflib Running setup.py install for rdflib Found existing installation: py 1.4.5 Uninstalling py: Successfully uninstalled py Running setup.py install for py Found existing installation: execnet 1.0.9 Uninstalling execnet: Successfully uninstalled execnet Running setup.py install for execnet no previously-included directories found matching 'doc/_build' warning: no previously-included files found matching '*.orig' warning: no previously-included files found matching '*.rej' warning: no previously-included files matching '*.pyc' found under directory 'execnet' warning: no previously-included files matching '*$py.class' found under directory 'execnet' warning: no previously-included files matching '*.pyc' found under directory 'testing' warning: no previously-included files matching '*$py.class' found under directory 'testing' no previously-included directories found matching '.svn' no previously-included directories found matching '.hg' Found existing installation: PyYAML 3.10 Uninstalling PyYAML: Successfully uninstalled PyYAML Running setup.py install for pyyaml checking if libyaml is compilable gcc-4.2 -fno-strict-aliasing -fno-common -dynamic -DNDEBUG -g -fwrapv -Os -Wall -Wstrict-prototypes -DENABLE_DTRACE -arch i386 -arch ppc -arch x86_64 -pipe -I/System/Library/Frameworks/Python.framework/Versions/2.6/include/python2.6 -c build/temp.macosx-10.6-universal-2.6/check_libyaml.c -o build/temp.macosx-10.6-universal-2.6/check_libyaml.o build/temp.macosx-10.6-universal-2.6/check_libyaml.c:2:18: error: yaml.h: No such file or directory build/temp.macosx-10.6-universal-2.6/check_libyaml.c: In function 'main': build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: 'yaml_parser_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: (Each undeclared identifier is reported only once build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: for each function it appears in.) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: expected ';' before 'parser' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: 'yaml_emitter_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: expected ';' before 'emitter' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: warning: implicit declaration of function 'yaml_parser_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: error: 'parser' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:9: warning: implicit declaration of function 'yaml_parser_delete' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: warning: implicit declaration of function 'yaml_emitter_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: error: 'emitter' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:12: warning: implicit declaration of function 'yaml_emitter_delete' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:2:18: error: yaml.h: No such file or directory build/temp.macosx-10.6-universal-2.6/check_libyaml.c: In function 'main': build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: 'yaml_parser_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: (Each undeclared identifier is reported only once build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: for each function it appears in.) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: expected ';' before 'parser' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: 'yaml_emitter_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: expected ';' before 'emitter' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: warning: implicit declaration of function 'yaml_parser_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: error: 'parser' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:9: warning: implicit declaration of function 'yaml_parser_delete' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: warning: implicit declaration of function 'yaml_emitter_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: error: 'emitter' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:12: warning: implicit declaration of function 'yaml_emitter_delete' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:2:18: error: yaml.h: No such file or directory build/temp.macosx-10.6-universal-2.6/check_libyaml.c: In function 'main': build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: 'yaml_parser_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: (Each undeclared identifier is reported only once build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: for each function it appears in.) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: expected ';' before 'parser' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: 'yaml_emitter_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: expected ';' before 'emitter' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: warning: implicit declaration of function 'yaml_parser_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: error: 'parser' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:9: warning: implicit declaration of function 'yaml_parser_delete' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: warning: implicit declaration of function 'yaml_emitter_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: error: 'emitter' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:12: warning: implicit declaration of function 'yaml_emitter_delete' lipo: can't open input file: /var/folders/Wp/Wp49uNCTGAq9KGDuyHFZDU+++TI/-Tmp-//cc3xmG6o.out (No such file or directory) libyaml is not found or a compiler error: forcing --without-libyaml (if libyaml is installed correctly, you may need to specify the option --include-dirs or uncomment and modify the parameter include_dirs in setup.cfg) Successfully installed selenium pytest pytest-xdist unittestzero pytest-mozwebqa rdflib py execnet pyyaml Cleaning up... [workspace] $ /bin/sh -xe /var/folders/Wp/Wp49uNCTGAq9KGDuyHFZDU+++TI/-Tmp-/hudson7396805463204623585.sh + py.test -n 2 -r fsxX --baseurl=http://developer-stage9.mozilla.org --api=rc '--environment=Firefox 7 on Mac OS X' --timeout=180000 --junitxml=results.xml --credentials=/Users/daveandpam/workspace/webqa-credentials/mdn.yaml --junitxml=results.xml
============================= test session starts ============================== platform darwin -- Python 2.6.1 -- pytest-2.2.0 gw0 I / gw1 I
gw0 [12] / gw1 [12] scheduling tests via LoadScheduling
x...........E ==================================== ERRORS ==================================== __________________ ERROR at teardown of TestLogin.test_login ___________________ [gw0] darwin -- Python 2.6.1 /Users/Shared/Jenkins/Home/jobs/mdn.staging/workspace/.env/bin/python item = <Function 'test_login'> def pytest_runtest_teardown(item): if hasattr(TestSetup, 'selenium') and TestSetup.selenium and not 'skip_selenium' in item.keywords: > _capture_debug(item) .env/lib/python2.6/site-packages/mozwebqa/mozwebqa.py:107: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ item = <Function 'test_login'> def _capture_debug(item): filename = _debug_path(item) _capture_screenshot(item, filename) > _capture_html(item, filename) .env/lib/python2.6/site-packages/mozwebqa/mozwebqa.py:389: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ item = <Function 'test_login'> filename = 'results/debug/test_login_TestLogin_test_login' def _capture_html(item, filename): f = open("%s.html" % filename, 'wb') if item.api.upper() == 'WEBDRIVER': f.write(TestSetup.selenium.page_source.encode('utf-8')) else: > f.write(TestSetup.selenium.get_html_source().encode('utf-8')) .env/lib/python2.6/site-packages/mozwebqa/mozwebqa.py:436: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = <selenium.selenium.selenium object at 0x104042a10> def get_html_source(self): """ Returns the entire HTML source between the opening and closing "html" tags. """ > return self.get_string("getHtmlSource", []) def set_cursor_position(self,locator,position): .env/lib/python2.6/site-packages/selenium/selenium.py:1538: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = <selenium.selenium.selenium object at 0x104042a10> verb = 'getHtmlSource', args = [] def get_string(self, verb, args): > result = self.do_command(verb, args) .env/lib/python2.6/site-packages/selenium/selenium.py:220: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = <selenium.selenium.selenium object at 0x104042a10> verb = 'getHtmlSource', args = [] def do_command(self, verb, args): conn = httplib.HTTPConnection(self.host, self.port) try: body = u'cmd=' + urllib.quote_plus(unicode(verb).encode('utf-8')) for i in range(len(args)): body += '&' + unicode(i+1) + '=' + \ urllib.quote_plus(unicode(args[i]).encode('utf-8')) if (None != self.sessionId): body += "&sessionId=" + unicode(self.sessionId) headers = { "Content-Type": "application/x-www-form-urlencoded; charset=utf-8" } conn.request("POST", "/selenium-server/driver/", body, headers) response = conn.getresponse() data = unicode(response.read(), "UTF-8") if (not data.startswith('OK')): > raise Exception, data E Exception: <html> E <head> E <title>Error 500 org.openqa.grid.common.exception.GridException: Session [afe4f0cfb1574f6bbed1973dc64622fa] not available - [ext. key 9aa7070bf3ae48c9b524828966ce18a3]</title> E </head> E <body> E <h2>HTTP ERROR: 500</h2><pre>org.openqa.grid.common.exception.GridException: Session [afe4f0cfb1574f6bbed1973dc64622fa] not available - [ext. key 9aa7070bf3ae48c9b524828966ce18a3]</pre> E <p>RequestURI=/selenium-server/driver/</p> E <p><i><small><a href="http://jetty.mortbay.org">Powered by Jetty://</a></small></i></p> E E E E E E E E E E E E E E E E E E E E E </body> E </html> .env/lib/python2.6/site-packages/selenium/selenium.py:214: Exception ----------------------- generated xml file: results.xml ------------------------ =========================== short test summary info ============================ XFAIL test_dev_derby.py::TestDevDerbyPage::()::test_derby_links_visible No derby winners on production yet =============== 11 passed, 1 xfailed, 1 error in 376.95 seconds ================ Build step 'Execute shell' marked build as failure Archiving artifacts Recording test results Finished: FAILURE

## hub.log
launch-hub:
     [java] Nov 28, 2011 2:49:41 PM org.openqa.grid.selenium.GridLauncher main
     [java] INFO: Launching a selenium grid server
     [java] Nov 28, 2011 2:49:44 PM org.openqa.jetty.http.HttpServer doStart
     [java] INFO: Version Jetty/5.1.x
     [java] Nov 28, 2011 2:49:44 PM org.openqa.jetty.util.FileResource <clinit>
     [java] INFO: Checking Resource aliases
     [java] Nov 28, 2011 2:49:46 PM org.openqa.jetty.util.Container start
     [java] INFO: Started org.openqa.jetty.jetty.servlet.WebApplicationHandler@f284fd4
     [java] Nov 28, 2011 2:49:46 PM org.openqa.jetty.util.Container start
     [java] INFO: Started WebApplicationContext[/,/]
     [java] Nov 28, 2011 2:49:46 PM org.openqa.jetty.http.SocketListener start
     [java] INFO: Started SocketListener on 0.0.0.0:4444
     [java] Nov 28, 2011 2:49:46 PM org.openqa.jetty.util.Container start
     [java] INFO: Started org.openqa.jetty.jetty.Server@32955cd5
     [java] Nov 28, 2011 2:56:59 PM org.openqa.grid.internal.RemoteProxy$CleanUpThread run
     [java] WARNING: session ext. key afe4f0cfb1574f6bbed1973dc64622fa has TIMED OUT and will be released
     [java] Nov 28, 2011 2:57:22 PM org.openqa.grid.internal.ActiveTestSessions getExistingSession
     [java] WARNING: Client requested session afe4f0cfb1574f6bbed1973dc64622fa that was terminated due to TIMEOUT
     [java] Nov 28, 2011 2:57:22 PM org.openqa.grid.internal.ActiveTestSessions getExistingSession
     [java] WARNING: Client requested session afe4f0cfb1574f6bbed1973dc64622fa that was terminated due to TIMEOUT

## node.log
launch-node-with-custom-profile:
     [java] Nov 28, 2011 2:49:46 PM org.openqa.grid.selenium.GridLauncher main
     [java] INFO: Launching a selenium grid node
     [java] 14:49:49.097 INFO - Java: Apple Inc. 20.4-b02-402
     [java] 14:49:49.099 INFO - OS: Mac OS X 10.6.8 x86_64
     [java] 14:49:49.107 INFO - v2.13.0, with Core v2.13.0. Built from revision 14922
     [java] 14:49:49.282 INFO - RemoteWebDriver instances should connect to: http://127.0.0.1:5555/wd/hub
     [java] 14:49:49.283 INFO - Version Jetty/5.1.x
     [java] 14:49:49.284 INFO - Started HttpContext[/selenium-server/driver,/selenium-server/driver]
     [java] 14:49:49.285 INFO - Started HttpContext[/selenium-server,/selenium-server]
     [java] 14:49:49.285 INFO - Started HttpContext[/,/]
     [java] 14:49:49.292 INFO - Started org.openqa.jetty.jetty.servlet.ServletHandler@f5db314
     [java] 14:49:49.293 INFO - Started HttpContext[/wd,/wd]
     [java] 14:49:49.299 INFO - Started SocketListener on 0.0.0.0:5555
     [java] 14:49:49.299 INFO - Started org.openqa.jetty.jetty.Server@45db05b2
     [java] 14:49:49.302 INFO - using the json request : {"class":"org.openqa.grid.common.RegistrationRequest","capabilities":[{"seleniumProtocol":"Selenium","browserName":"Firefox 3.6 on Mac OS X","maxInstances":5},{"seleniumProtocol":"Selenium","browserName":"Firefox 4 on Mac OS X","maxInstances":5},{"seleniumProtocol":"Selenium","browserName":"Firefox 5 on Mac OS X","maxInstances":5},{"seleniumProtocol":"Selenium","browserName":"Firefox 6 on Mac OS X","maxInstances":5},{"seleniumProtocol":"Selenium","browserName":"Firefox 7 on Mac OS X","maxInstances":1},{"seleniumProtocol":"Selenium","browserName":"Firefox Beta on Mac OS X","maxInstances":5},{"seleniumProtocol":"Selenium","browserName":"Firefox Aurora on Mac OS X","maxInstances":5},{"seleniumProtocol":"Selenium","browserName":"Firefox Nightly on Mac OS X","maxInstances":5},{"platform":"MAC","seleniumProtocol":"WebDriver","firefox_binary":"/Applications/Firefox 3.6.app/Contents/MacOS/firefox-bin","browserName":"firefox","maxInstances":5,"version":"3.6"},{"platform":"MAC","seleniumProtocol":"WebDriver","firefox_binary":"/Applications/Firefox 4.app/Contents/MacOS/firefox-bin","browserName":"firefox","maxInstances":5,"version":"4"},{"platform":"MAC","seleniumProtocol":"WebDriver","firefox_binary":"/Applications/Firefox 5.app/Contents/MacOS/firefox-bin","browserName":"firefox","maxInstances":5,"version":"5"},{"platform":"MAC","seleniumProtocol":"WebDriver","firefox_binary":"/Applications/Firefox 6.app/Contents/MacOS/firefox-bin","browserName":"firefox","maxInstances":5,"version":"6"},{"platform":"MAC","seleniumProtocol":"WebDriver","firefox_binary":"/Applications/Firefox 7.app/Contents/MacOS/firefox-bin","browserName":"firefox","maxInstances":5,"version":"7"},{"platform":"MAC","seleniumProtocol":"WebDriver","firefox_binary":"/Applications/Firefox Beta.app/Contents/MacOS/firefox-bin","browserName":"firefox","maxInstances":5,"version":"beta"},{"platform":"MAC","seleniumProtocol":"WebDriver","firefox_binary":"/Applications/Aurora.app/Contents/MacOS/firefox-bin","browserName":"firefox","maxInstances":5,"version":"aurora"},{"platform":"MAC","seleniumProtocol":"WebDriver","firefox_binary":"/Applications/Nightly.app/Contents/MacOS/firefox-bin","browserName":"firefox","maxInstances":5,"version":"nightly"}],"configuration":{"port":5555,"nodeConfig":"mac.json","host":"localhost","hubHost":"localhost","registerCycle":5000,"hub":"http://localhost:4444/grid/register","remoteHost":"http://localhost:5555","register":true,"proxy":"org.openqa.grid.selenium.proxy.DefaultRemoteProxy","firefoxProfileTemplate":"/Users/daveandpam/workspace/moz-grid-config/firefoxprofiles/certificateExceptions","maxSession":5,"role":"node","hubPort":4444,"timeout":180000}}
     [java] 14:49:49.304 INFO - starting auto register thread. Will try to register every 5000 ms.
     [java] 14:49:49.304 INFO - Registering the node to hub :http://localhost:4444/grid/register
     [java] 14:49:54.840 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@191a01dd at URL: /status)
     [java] 14:49:54.841 INFO - Done: /status
     [java] 14:49:59.878 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6ee1dac2 at URL: /status)
     [java] 14:49:59.879 INFO - Done: /status
     [java] 14:50:04.882 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@30e34726 at URL: /status)
     [java] 14:50:04.883 INFO - Done: /status
     [java] 14:50:09.903 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6446d228 at URL: /status)
     [java] 14:50:09.903 INFO - Done: /status
     [java] 14:50:14.907 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@2ce99681 at URL: /status)
     [java] 14:50:14.907 INFO - Done: /status
     [java] 14:50:17.239 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@19be4777 at URL: /status)
     [java] 14:50:17.239 INFO - Done: /status
     [java] 14:50:19.911 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@92f1bf0 at URL: /status)
     [java] 14:50:19.911 INFO - Done: /status
     [java] 14:50:24.914 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@2d82ef6b at URL: /status)
     [java] 14:50:24.914 INFO - Done: /status
     [java] 14:50:29.952 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@343aff84 at URL: /status)
     [java] 14:50:29.953 INFO - Done: /status
     [java] 14:50:34.956 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@68a53de4 at URL: /status)
     [java] 14:50:34.956 INFO - Done: /status
     [java] 14:50:39.959 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@46b4be3d at URL: /status)
     [java] 14:50:39.960 INFO - Done: /status
     [java] 14:50:44.963 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@720e4245 at URL: /status)
     [java] 14:50:44.964 INFO - Done: /status
     [java] 14:50:49.967 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@5f1eb199 at URL: /status)
     [java] 14:50:49.967 INFO - Done: /status
     [java] 14:50:54.971 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@5c95da38 at URL: /status)
     [java] 14:50:54.972 INFO - Done: /status
     [java] 14:50:59.975 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@1380cf2a at URL: /status)
     [java] 14:50:59.976 INFO - Done: /status
     [java] 14:51:04.982 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@54ee3aa7 at URL: /status)
     [java] 14:51:04.982 INFO - Done: /status
     [java] 14:51:09.986 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@2bd9e282 at URL: /status)
     [java] 14:51:09.986 INFO - Done: /status
     [java] 14:51:14.990 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@5bf0aecc at URL: /status)
     [java] 14:51:14.990 INFO - Done: /status
     [java] 14:51:16.921 INFO - Checking Resource aliases
     [java] 14:51:16.926 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:51:16.929 INFO - creating new remote session
     [java] 14:51:16.996 INFO - Allocated session f196aae65db84f4d88fb15fabd287d33 for http://developer-stage9.mozilla.org, launching...
     [java] 14:51:17.127 INFO - Preparing Firefox profile...
     [java] 14:51:19.563 INFO - Launching Firefox...
     [java] 14:51:20.002 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@257b40fe at URL: /status)
     [java] 14:51:20.004 INFO - Done: /status
     [java] 14:51:22.099 INFO - Got result: OK,f196aae65db84f4d88fb15fabd287d33 on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:22.108 INFO - Command request: setTimeout[180000, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:22.122 INFO - Got result: OK on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:22.130 INFO - Command request: setContext[test_dev_derby.TestDevDerbyPage.test_derby_links_visible, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:22.138 INFO - Got result: OK on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:22.154 INFO - Command request: open[en-US/demos/devderby, True] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:25.013 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@1b192059 at URL: /status)
     [java] 14:51:25.014 INFO - Done: /status
     [java] 14:51:30.017 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6e20f237 at URL: /status)
     [java] 14:51:30.017 INFO - Done: /status
     [java] 14:51:32.905 INFO - Got result: OK on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:32.918 INFO - Command request: waitForPageToLoad[180000, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:32.928 INFO - Got result: OK on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:32.935 INFO - Command request: isVisible[css=#nav-derby>ul>li>em, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:32.948 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:32.955 INFO - Command request: isElementPresent[css=#nav-derby>ul>li>em, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:32.964 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:32.975 INFO - Command request: isVisible[css=#nav-derby>ul:nth-child(1)>li:nth-child(2)>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.004 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.022 INFO - Command request: isElementPresent[css=#nav-derby>ul:nth-child(1)>li:nth-child(2)>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.033 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.049 INFO - Command request: isVisible[css=#nav-derby>ul:nth-child(1)>li:nth-child(3)>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.057 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.065 INFO - Command request: isElementPresent[css=#nav-derby>ul:nth-child(1)>li:nth-child(3)>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.124 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.134 INFO - Command request: isVisible[css=#nav-derby>ul:nth-child(1)>li:nth-child(4)>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.161 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.171 INFO - Command request: isElementPresent[css=#nav-derby>ul:nth-child(1)>li:nth-child(4)>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.177 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.210 INFO - Command request: isVisible[css=#nav-derby>ul:nth-child(1)>li:nth-child(5)>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.218 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.231 INFO - Command request: isElementPresent[css=#nav-derby>ul:nth-child(1)>li:nth-child(5)>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.243 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.288 INFO - Command request: isVisible[css=#nav-derby>ul:nth-child(1)>li:nth-child(6)>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.299 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.306 INFO - Command request: isElementPresent[css=#nav-derby>ul:nth-child(1)>li:nth-child(6)>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.312 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.334 INFO - Command request: isVisible[css=.submit>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.341 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.352 INFO - Command request: isElementPresent[css=.submit>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.360 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.369 INFO - Command request: isVisible[css=.presents>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.376 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.384 INFO - Command request: isElementPresent[css=.presents>a, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.393 INFO - Got result: OK,true on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.399 INFO - Command request: isVisible[css=#prev-winner>h1, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.406 INFO - Got result: ERROR: Element css=#prev-winner>h1 not found on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:33.450 INFO - Command request: captureEntirePageScreenshotToString[, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:34.208 INFO - Got result: [base64 encoded PNG] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:34.296 INFO - Command request: getHtmlSource[, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:34.528 INFO - Got result: [HTML source] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:34.536 INFO - Command request: testComplete[, ] on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:34.536 INFO - Killing Firefox...
     [java] 14:51:34.716 INFO - Got result: OK on session f196aae65db84f4d88fb15fabd287d33
     [java] 14:51:34.726 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:51:34.726 INFO - creating new remote session
     [java] 14:51:34.728 INFO - Allocated session c98dc19483b943d082aaae2847768f37 for http://developer-stage9.mozilla.org, launching...
     [java] 14:51:34.820 INFO - Preparing Firefox profile...
     [java] 14:51:35.023 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@3a42f352 at URL: /status)
     [java] 14:51:35.034 INFO - Done: /status
     [java] 14:51:37.115 INFO - Launching Firefox...
     [java] 14:51:39.629 INFO - Got result: OK,c98dc19483b943d082aaae2847768f37 on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:39.638 INFO - Command request: setTimeout[180000, ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:39.644 INFO - Got result: OK on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:39.652 INFO - Command request: setContext[test_dev_derby.TestDevDerbyPage.test_are_footer_links_visible, ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:39.657 INFO - Got result: OK on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:39.668 INFO - Command request: open[en-US/demos/devderby, True] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:40.050 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@4013fba1 at URL: /status)
     [java] 14:51:40.050 INFO - Done: /status
     [java] 14:51:45.054 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@2e82674b at URL: /status)
     [java] 14:51:45.054 INFO - Done: /status
     [java] 14:51:46.209 INFO - Got result: OK on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.216 INFO - Command request: waitForPageToLoad[180000, ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.224 INFO - Got result: OK on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.232 INFO - Command request: isVisible[css=#legal > img, ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.252 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.260 INFO - Command request: isElementPresent[css=#legal > img, ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.267 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.274 INFO - Command request: isVisible[css=#footbar > div.wrap > p > a, ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.285 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.291 INFO - Command request: isElementPresent[css=#footbar > div.wrap > p > a, ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.312 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.319 INFO - Command request: isVisible[css=#legal > p > a:nth-child(1), ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.330 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.336 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(1), ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.342 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.356 INFO - Command request: isVisible[css=#legal > p > a:nth-child(2), ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.381 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.388 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(2), ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.394 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.461 INFO - Command request: isVisible[css=#legal > p > a:nth-child(3), ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.480 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.487 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(3), ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.496 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.504 INFO - Command request: isVisible[css=#legal > p > a:nth-child(4), ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.516 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.524 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(4), ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.565 INFO - Got result: OK,true on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:46.576 INFO - Command request: captureEntirePageScreenshotToString[, ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:47.339 INFO - Got result: [base64 encoded PNG] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:47.463 INFO - Command request: getHtmlSource[, ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:47.539 INFO - Got result: [HTML source] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:47.555 INFO - Command request: testComplete[, ] on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:47.556 INFO - Killing Firefox...
     [java] 14:51:47.628 INFO - Got result: OK on session c98dc19483b943d082aaae2847768f37
     [java] 14:51:47.640 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:51:47.640 INFO - creating new remote session
     [java] 14:51:47.644 INFO - Allocated session d5bfa2061ffb402c86bb0f11b672d549 for http://developer-stage9.mozilla.org, launching...
     [java] 14:51:47.679 INFO - Preparing Firefox profile...
     [java] 14:51:50.058 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@269be2b5 at URL: /status)
     [java] 14:51:50.059 INFO - Done: /status
     [java] 14:51:50.079 INFO - Launching Firefox...
     [java] 14:51:52.518 INFO - Got result: OK,d5bfa2061ffb402c86bb0f11b672d549 on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:51:52.525 INFO - Command request: setTimeout[180000, ] on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:51:52.543 INFO - Got result: OK on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:51:52.550 INFO - Command request: setContext[test_dev_derby.TestDevDerbyPage.test_are_previous_challenges_present, ] on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:51:52.554 INFO - Got result: OK on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:51:52.564 INFO - Command request: open[en-US/demos/devderby, True] on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:51:55.063 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@66e7b3f2 at URL: /status)
     [java] 14:51:55.064 INFO - Done: /status
     [java] 14:51:59.582 INFO - Got result: OK on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:51:59.590 INFO - Command request: waitForPageToLoad[180000, ] on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:51:59.596 INFO - Got result: OK on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:51:59.603 INFO - Command request: getCssCount[css=.ul.previous>li>h3, ] on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:51:59.609 INFO - Got result: OK,0 on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:51:59.618 INFO - Command request: captureEntirePageScreenshotToString[, ] on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:52:00.067 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@78ba6c13 at URL: /status)
     [java] 14:52:00.067 INFO - Done: /status
     [java] 14:52:00.377 INFO - Got result: [base64 encoded PNG] on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:52:00.484 INFO - Command request: getHtmlSource[, ] on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:52:00.501 INFO - Got result: [HTML source] on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:52:00.508 INFO - Command request: testComplete[, ] on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:52:00.508 INFO - Killing Firefox...
     [java] 14:52:00.672 INFO - Got result: OK on session d5bfa2061ffb402c86bb0f11b672d549
     [java] 14:52:00.678 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:52:00.678 INFO - creating new remote session
     [java] 14:52:00.678 INFO - Allocated session a458f40fed0f451abf74bf5ef02df5fb for http://developer-stage9.mozilla.org, launching...
     [java] 14:52:00.713 INFO - Preparing Firefox profile...
     [java] 14:52:03.030 INFO - Launching Firefox...
     [java] 14:52:05.071 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@c292cb2 at URL: /status)
     [java] 14:52:05.071 INFO - Done: /status
     [java] 14:52:05.565 INFO - Got result: OK,a458f40fed0f451abf74bf5ef02df5fb on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:05.574 INFO - Command request: setTimeout[180000, ] on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:05.581 INFO - Got result: OK on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:05.587 INFO - Command request: setContext[test_dev_derby.TestDevDerbyPage.test_judge_images_visible, ] on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:05.591 INFO - Got result: OK on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:05.602 INFO - Command request: open[en-US/demos/devderby, True] on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:10.075 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@1710278e at URL: /status)
     [java] 14:52:10.075 INFO - Done: /status
     [java] 14:52:11.851 INFO - Got result: OK on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:11.858 INFO - Command request: waitForPageToLoad[180000, ] on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:11.863 INFO - Got result: OK on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:11.870 INFO - Command request: getCssCount[css=.judges>vcard>h3>a>img, ] on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:11.876 INFO - Got result: OK,0 on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:11.887 INFO - Command request: captureEntirePageScreenshotToString[, ] on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:12.622 INFO - Got result: [base64 encoded PNG] on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:12.704 INFO - Command request: getHtmlSource[, ] on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:12.754 INFO - Got result: [HTML source] on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:12.761 INFO - Command request: testComplete[, ] on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:12.761 INFO - Killing Firefox...
     [java] 14:52:12.940 INFO - Got result: OK on session a458f40fed0f451abf74bf5ef02df5fb
     [java] 14:52:12.947 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:52:12.948 INFO - creating new remote session
     [java] 14:52:12.949 INFO - Allocated session f21bec4fc567454089cd2393aeaad626 for http://developer-stage9.mozilla.org, launching...
     [java] 14:52:12.981 INFO - Preparing Firefox profile...
     [java] 14:52:15.079 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6bc5af2e at URL: /status)
     [java] 14:52:15.080 INFO - Done: /status
     [java] 14:52:15.230 INFO - Launching Firefox...
     [java] 14:52:17.666 INFO - Got result: OK,f21bec4fc567454089cd2393aeaad626 on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:17.675 INFO - Command request: setTimeout[180000, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:17.684 INFO - Got result: OK on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:17.690 INFO - Command request: setContext[test_homepage.TestHomepage.test_footer_links, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:17.695 INFO - Got result: OK on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:17.716 INFO - Command request: open[/demos, True] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:20.084 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6762ba99 at URL: /status)
     [java] 14:52:20.084 INFO - Done: /status
     [java] 14:52:25.088 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@4bb7b407 at URL: /status)
     [java] 14:52:25.088 INFO - Done: /status
     [java] 14:52:29.144 INFO - Got result: OK on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.151 INFO - Command request: waitForPageToLoad[180000, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.159 INFO - Got result: OK on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.167 INFO - Command request: isVisible[css=#legal > img, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.180 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.188 INFO - Command request: isElementPresent[css=#legal > img, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.202 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.209 INFO - Command request: isVisible[css=.feed > a, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.217 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.224 INFO - Command request: isElementPresent[css=.feed > a, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.229 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.238 INFO - Command request: isVisible[css=#footbar > div.wrap > p > a, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.249 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.255 INFO - Command request: isElementPresent[css=#footbar > div.wrap > p > a, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.261 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.275 INFO - Command request: isVisible[css=#legal > p > a:nth-child(1), ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.283 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.291 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(1), ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.297 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.308 INFO - Command request: isVisible[css=#legal > p > a:nth-child(2), ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.315 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.323 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(2), ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.328 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.340 INFO - Command request: isVisible[css=#legal > p > a:nth-child(3), ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.359 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.379 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(3), ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.396 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.403 INFO - Command request: isVisible[css=#legal > p > a:nth-child(4), ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.413 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.420 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(4), ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.429 INFO - Got result: OK,true on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:29.438 INFO - Command request: captureEntirePageScreenshotToString[, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:30.091 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@9c4ff2c at URL: /status)
     [java] 14:52:30.091 INFO - Done: /status
     [java] 14:52:30.362 INFO - Got result: [base64 encoded PNG] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:30.480 INFO - Command request: getHtmlSource[, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:30.507 INFO - Got result: [HTML source] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:30.522 INFO - Command request: testComplete[, ] on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:30.522 INFO - Killing Firefox...
     [java] 14:52:30.697 INFO - Got result: OK on session f21bec4fc567454089cd2393aeaad626
     [java] 14:52:30.706 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:52:30.707 INFO - creating new remote session
     [java] 14:52:30.708 INFO - Allocated session 2a75947001aa4e23810b8d3cdeac6a39 for http://developer-stage9.mozilla.org, launching...
     [java] 14:52:30.752 INFO - Preparing Firefox profile...
     [java] 14:52:33.075 INFO - Launching Firefox...
     [java] 14:52:35.095 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@1c33c658 at URL: /status)
     [java] 14:52:35.096 INFO - Done: /status
     [java] 14:52:35.452 INFO - Got result: OK,2a75947001aa4e23810b8d3cdeac6a39 on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:35.460 INFO - Command request: setTimeout[180000, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:35.470 INFO - Got result: OK on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:35.477 INFO - Command request: setContext[test_homepage.TestHomepage.test_header_links, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:35.481 INFO - Got result: OK on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:35.491 INFO - Command request: open[/demos, True] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:40.099 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@f5d8d75 at URL: /status)
     [java] 14:52:40.099 INFO - Done: /status
     [java] 14:52:45.103 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@3af2164f at URL: /status)
     [java] 14:52:45.103 INFO - Done: /status
     [java] 14:52:46.228 INFO - Got result: OK on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.234 INFO - Command request: waitForPageToLoad[180000, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.239 INFO - Got result: OK on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.245 INFO - Command request: isVisible[css=.toggle, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.252 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.259 INFO - Command request: isElementPresent[css=.toggle, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.264 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.271 INFO - Command request: isVisible[css=.docs, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.281 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.287 INFO - Command request: isElementPresent[css=.docs, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.293 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.299 INFO - Command request: isVisible[css=.demos, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.307 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.313 INFO - Command request: isElementPresent[css=.demos, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.326 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.333 INFO - Command request: isVisible[css=.learning, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.340 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.348 INFO - Command request: isElementPresent[css=.learning, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.362 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.380 INFO - Command request: isVisible[css=.community, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.390 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.396 INFO - Command request: isElementPresent[css=.community, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.404 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.410 INFO - Command request: isVisible[css=.wrap > p:nth-child(1) > a, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.422 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.433 INFO - Command request: isElementPresent[css=.wrap > p:nth-child(1) > a, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.442 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.449 INFO - Command request: isVisible[css=.wrap > p:nth-child(2) > a, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.460 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.467 INFO - Command request: isElementPresent[css=.wrap > p:nth-child(2) > a, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.476 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.483 INFO - Command request: isVisible[css=#q, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.492 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.502 INFO - Command request: isElementPresent[css=#q, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.512 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.552 INFO - Command request: isVisible[css=#demos-head > h1, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.564 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.571 INFO - Command request: isElementPresent[css=#demos-head > h1, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.581 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.588 INFO - Command request: isVisible[css=.learning, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.599 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.606 INFO - Command request: isElementPresent[css=.learning, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.611 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.618 INFO - Command request: isVisible[css=.community, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.625 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.632 INFO - Command request: isElementPresent[css=.community, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.642 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.649 INFO - Command request: isVisible[css=.wrap > p:nth-child(1) > a, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.656 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.663 INFO - Command request: isElementPresent[css=.wrap > p:nth-child(1) > a, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.672 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.678 INFO - Command request: isVisible[css=.wrap > p:nth-child(2) > a, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.685 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.692 INFO - Command request: isElementPresent[css=.wrap > p:nth-child(2) > a, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.702 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.716 INFO - Command request: isVisible[css=#q, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.728 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.765 INFO - Command request: isElementPresent[css=#q, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.785 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.801 INFO - Command request: isVisible[css=#demos-head > h1, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.811 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.818 INFO - Command request: isElementPresent[css=#demos-head > h1, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.827 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.834 INFO - Command request: isVisible[css=.learnmore > a, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.841 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.855 INFO - Command request: isElementPresent[css=.learnmore > a, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.865 INFO - Got result: OK,true on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:46.939 INFO - Command request: captureEntirePageScreenshotToString[, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:47.855 INFO - Got result: [base64 encoded PNG] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:47.957 INFO - Command request: getHtmlSource[, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:47.981 INFO - Got result: [HTML source] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:47.989 INFO - Command request: testComplete[, ] on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:47.989 INFO - Killing Firefox...
     [java] 14:52:48.054 INFO - Got result: OK on session 2a75947001aa4e23810b8d3cdeac6a39
     [java] 14:52:48.063 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:52:48.063 INFO - creating new remote session
     [java] 14:52:48.064 INFO - Allocated session 2e7e668f1b9e4c828f90800be7d9da39 for http://developer-stage9.mozilla.org, launching...
     [java] 14:52:48.106 INFO - Preparing Firefox profile...
     [java] 14:52:50.107 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@4412dd76 at URL: /status)
     [java] 14:52:50.107 INFO - Done: /status
     [java] 14:52:50.287 INFO - Launching Firefox...
     [java] 14:52:52.796 INFO - Got result: OK,2e7e668f1b9e4c828f90800be7d9da39 on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:52.805 INFO - Command request: setTimeout[180000, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:52.814 INFO - Got result: OK on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:52.821 INFO - Command request: setContext[test_homepage.TestHomepage.test_demo_image, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:52.825 INFO - Got result: OK on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:52.835 INFO - Command request: open[/demos, True] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:55.111 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@7e543cb1 at URL: /status)
     [java] 14:52:55.111 INFO - Done: /status
     [java] 14:52:59.773 INFO - Got result: OK on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.779 INFO - Command request: waitForPageToLoad[180000, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.783 INFO - Got result: OK on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.789 INFO - Command request: getCssCount[css=.demo > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.795 INFO - Got result: OK,12 on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.802 INFO - Command request: isVisible[css=.demo:nth-child(1) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.810 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.816 INFO - Command request: isElementPresent[css=.demo:nth-child(1) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.822 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.828 INFO - Command request: isVisible[css=.demo:nth-child(2) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.836 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.842 INFO - Command request: isElementPresent[css=.demo:nth-child(2) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.848 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.854 INFO - Command request: isVisible[css=.demo:nth-child(3) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.862 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.872 INFO - Command request: isElementPresent[css=.demo:nth-child(3) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.877 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.884 INFO - Command request: isVisible[css=.demo:nth-child(4) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.892 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.906 INFO - Command request: isElementPresent[css=.demo:nth-child(4) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.915 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.921 INFO - Command request: isVisible[css=.demo:nth-child(5) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.928 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.935 INFO - Command request: isElementPresent[css=.demo:nth-child(5) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.940 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.947 INFO - Command request: isVisible[css=.demo:nth-child(6) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.955 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.961 INFO - Command request: isElementPresent[css=.demo:nth-child(6) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.967 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.976 INFO - Command request: isVisible[css=.demo:nth-child(7) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.983 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.990 INFO - Command request: isElementPresent[css=.demo:nth-child(7) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:52:59.995 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.002 INFO - Command request: isVisible[css=.demo:nth-child(8) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.017 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.025 INFO - Command request: isElementPresent[css=.demo:nth-child(8) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.030 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.037 INFO - Command request: isVisible[css=.demo:nth-child(9) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.044 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.051 INFO - Command request: isElementPresent[css=.demo:nth-child(9) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.059 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.065 INFO - Command request: isVisible[css=.demo:nth-child(10) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.076 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.083 INFO - Command request: isElementPresent[css=.demo:nth-child(10) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.088 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.095 INFO - Command request: isVisible[css=.demo:nth-child(11) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.102 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.113 INFO - Command request: isElementPresent[css=.demo:nth-child(11) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.120 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@683c9314 at URL: /status)
     [java] 14:53:00.121 INFO - Done: /status
     [java] 14:53:00.123 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.129 INFO - Command request: isVisible[css=.demo:nth-child(12) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.140 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.147 INFO - Command request: isElementPresent[css=.demo:nth-child(12) > .demo-title > a > img, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.152 INFO - Got result: OK,true on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:00.160 INFO - Command request: captureEntirePageScreenshotToString[, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:01.095 INFO - Got result: [base64 encoded PNG] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:01.197 INFO - Command request: getHtmlSource[, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:01.222 INFO - Got result: [HTML source] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:01.230 INFO - Command request: testComplete[, ] on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:01.230 INFO - Killing Firefox...
     [java] 14:53:01.393 INFO - Got result: OK on session 2e7e668f1b9e4c828f90800be7d9da39
     [java] 14:53:01.405 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:53:01.405 INFO - creating new remote session
     [java] 14:53:01.406 INFO - Allocated session b0308476992a4aa790486f759688397d for http://developer-stage9.mozilla.org, launching...
     [java] 14:53:01.439 INFO - Preparing Firefox profile...
     [java] 14:53:03.751 INFO - Launching Firefox...
     [java] 14:53:05.125 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@59566a6c at URL: /status)
     [java] 14:53:05.125 INFO - Done: /status
     [java] 14:53:06.189 INFO - Got result: OK,b0308476992a4aa790486f759688397d on session b0308476992a4aa790486f759688397d
     [java] 14:53:06.197 INFO - Command request: setTimeout[180000, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:06.207 INFO - Got result: OK on session b0308476992a4aa790486f759688397d
     [java] 14:53:06.213 INFO - Command request: setContext[test_homepage.TestHomepage.test_demo_title, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:06.218 INFO - Got result: OK on session b0308476992a4aa790486f759688397d
     [java] 14:53:06.228 INFO - Command request: open[/demos, True] on session b0308476992a4aa790486f759688397d
     [java] 14:53:10.128 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@2075c78d at URL: /status)
     [java] 14:53:10.128 INFO - Done: /status
     [java] 14:53:13.063 INFO - Got result: OK on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.069 INFO - Command request: waitForPageToLoad[180000, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.077 INFO - Got result: OK on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.083 INFO - Command request: getCssCount[css=.demo > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.091 INFO - Got result: OK,12 on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.097 INFO - Command request: isVisible[css=.demo:nth-child(1) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.104 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.111 INFO - Command request: isElementPresent[css=.demo:nth-child(1) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.119 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.129 INFO - Command request: isVisible[css=.demo:nth-child(2) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.138 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.145 INFO - Command request: isElementPresent[css=.demo:nth-child(2) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.155 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.163 INFO - Command request: isVisible[css=.demo:nth-child(3) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.175 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.182 INFO - Command request: isElementPresent[css=.demo:nth-child(3) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.197 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.204 INFO - Command request: isVisible[css=.demo:nth-child(4) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.215 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.225 INFO - Command request: isElementPresent[css=.demo:nth-child(4) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.236 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.244 INFO - Command request: isVisible[css=.demo:nth-child(5) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.251 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.258 INFO - Command request: isElementPresent[css=.demo:nth-child(5) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.263 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.270 INFO - Command request: isVisible[css=.demo:nth-child(6) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.277 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.283 INFO - Command request: isElementPresent[css=.demo:nth-child(6) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.289 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.295 INFO - Command request: isVisible[css=.demo:nth-child(7) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.307 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.313 INFO - Command request: isElementPresent[css=.demo:nth-child(7) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.319 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.325 INFO - Command request: isVisible[css=.demo:nth-child(8) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.339 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.349 INFO - Command request: isElementPresent[css=.demo:nth-child(8) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.355 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.363 INFO - Command request: isVisible[css=.demo:nth-child(9) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.370 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.377 INFO - Command request: isElementPresent[css=.demo:nth-child(9) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.382 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.389 INFO - Command request: isVisible[css=.demo:nth-child(10) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.401 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.412 INFO - Command request: isElementPresent[css=.demo:nth-child(10) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.421 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.427 INFO - Command request: isVisible[css=.demo:nth-child(11) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.434 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.444 INFO - Command request: isElementPresent[css=.demo:nth-child(11) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.453 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.459 INFO - Command request: isVisible[css=.demo:nth-child(12) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.470 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.477 INFO - Command request: isElementPresent[css=.demo:nth-child(12) > .demo-title > a, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.483 INFO - Got result: OK,true on session b0308476992a4aa790486f759688397d
     [java] 14:53:13.491 INFO - Command request: captureEntirePageScreenshotToString[, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:14.421 INFO - Got result: [base64 encoded PNG] on session b0308476992a4aa790486f759688397d
     [java] 14:53:14.519 INFO - Command request: getHtmlSource[, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:14.541 INFO - Got result: [HTML source] on session b0308476992a4aa790486f759688397d
     [java] 14:53:14.549 INFO - Command request: testComplete[, ] on session b0308476992a4aa790486f759688397d
     [java] 14:53:14.549 INFO - Killing Firefox...
     [java] 14:53:14.746 INFO - Got result: OK on session b0308476992a4aa790486f759688397d
     [java] 14:53:14.766 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:53:14.766 INFO - creating new remote session
     [java] 14:53:14.766 INFO - Allocated session 9fed71c18fff42e3a392cd6defd3f5e4 for http://developer-stage9.mozilla.org, launching...
     [java] 14:53:14.811 INFO - Preparing Firefox profile...
     [java] 14:53:15.147 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@5d85fe0c at URL: /status)
     [java] 14:53:15.148 INFO - Done: /status
     [java] 14:53:17.023 INFO - Launching Firefox...
     [java] 14:53:19.405 INFO - Got result: OK,9fed71c18fff42e3a392cd6defd3f5e4 on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:19.413 INFO - Command request: setTimeout[180000, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:19.423 INFO - Got result: OK on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:19.429 INFO - Command request: setContext[test_learn_page.TestLearnPage.test_header_links_visible, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:19.434 INFO - Got result: OK on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:19.444 INFO - Command request: open[en-US/learn, True] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:20.152 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@36511e0a at URL: /status)
     [java] 14:53:20.152 INFO - Done: /status
     [java] 14:53:25.155 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@46ac97cc at URL: /status)
     [java] 14:53:25.155 INFO - Done: /status
     [java] 14:53:25.198 INFO - Got result: OK on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.205 INFO - Command request: waitForPageToLoad[180000, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.210 INFO - Got result: OK on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.219 INFO - Command request: isVisible[css=.toggle, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.231 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.238 INFO - Command request: isElementPresent[css=.toggle, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.243 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.251 INFO - Command request: isVisible[css=.docs, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.258 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.264 INFO - Command request: isElementPresent[css=.docs, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.273 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.281 INFO - Command request: isVisible[css=.demos, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.288 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.294 INFO - Command request: isElementPresent[css=.demos, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.300 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.306 INFO - Command request: isVisible[css=.learning, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.319 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.326 INFO - Command request: isElementPresent[css=.learning, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.331 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.338 INFO - Command request: isVisible[css=.community, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.350 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.356 INFO - Command request: isElementPresent[css=.community, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.361 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.367 INFO - Command request: isVisible[css=.wrap > p:nth-child(1) > a, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.374 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.383 INFO - Command request: isElementPresent[css=.wrap > p:nth-child(1) > a, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.389 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.395 INFO - Command request: isVisible[css=.wrap > p:nth-child(2) > a, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.402 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.408 INFO - Command request: isElementPresent[css=.wrap > p:nth-child(2) > a, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.414 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.425 INFO - Command request: isVisible[css=#q, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.433 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.442 INFO - Command request: isElementPresent[css=#q, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.447 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.454 INFO - Command request: isVisible[css=.learning, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.461 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.469 INFO - Command request: isElementPresent[css=.learning, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.475 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.481 INFO - Command request: isVisible[css=.community, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.492 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.498 INFO - Command request: isElementPresent[css=.community, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.506 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.539 INFO - Command request: isVisible[css=.wrap > p:nth-child(1) > a, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.562 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.568 INFO - Command request: isElementPresent[css=.wrap > p:nth-child(1) > a, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.574 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.580 INFO - Command request: isVisible[css=.wrap > p:nth-child(2) > a, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.587 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.595 INFO - Command request: isElementPresent[css=.wrap > p:nth-child(2) > a, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.600 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.609 INFO - Command request: isVisible[css=#q, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.616 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.623 INFO - Command request: isElementPresent[css=#q, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.630 INFO - Got result: OK,true on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:25.644 INFO - Command request: captureEntirePageScreenshotToString[, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:26.020 INFO - Got result: [base64 encoded PNG] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:26.054 INFO - Command request: getHtmlSource[, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:26.064 INFO - Got result: [HTML source] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:26.071 INFO - Command request: testComplete[, ] on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:26.071 INFO - Killing Firefox...
     [java] 14:53:26.219 INFO - Got result: OK on session 9fed71c18fff42e3a392cd6defd3f5e4
     [java] 14:53:26.233 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:53:26.234 INFO - creating new remote session
     [java] 14:53:26.234 INFO - Allocated session 6c96eb463044491fa1d046cdba30d0ea for http://developer-stage9.mozilla.org, launching...
     [java] 14:53:26.263 INFO - Preparing Firefox profile...
     [java] 14:53:28.494 INFO - Launching Firefox...
     [java] 14:53:30.159 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@7b34c5ff at URL: /status)
     [java] 14:53:30.160 INFO - Done: /status
     [java] 14:53:30.888 INFO - Got result: OK,6c96eb463044491fa1d046cdba30d0ea on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:30.895 INFO - Command request: setTimeout[180000, ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:30.909 INFO - Got result: OK on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:30.916 INFO - Command request: setContext[test_learn_page.TestLearnPage.test_are_footer_links_visible, ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:30.920 INFO - Got result: OK on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:30.930 INFO - Command request: open[en-US/learn, True] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:35.163 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6b248979 at URL: /status)
     [java] 14:53:35.163 INFO - Done: /status
     [java] 14:53:36.660 INFO - Got result: OK on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.665 INFO - Command request: waitForPageToLoad[180000, ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.671 INFO - Got result: OK on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.678 INFO - Command request: isVisible[css=#legal > img, ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.684 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.691 INFO - Command request: isElementPresent[css=#legal > img, ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.696 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.703 INFO - Command request: isVisible[css=#footbar > div.wrap > p > a, ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.713 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.720 INFO - Command request: isElementPresent[css=#footbar > div.wrap > p > a, ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.728 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.734 INFO - Command request: isVisible[css=#legal > p > a:nth-child(1), ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.745 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.751 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(1), ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.757 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.763 INFO - Command request: isVisible[css=#legal > p > a:nth-child(2), ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.773 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.788 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(2), ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.794 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.804 INFO - Command request: isVisible[css=#legal > p > a:nth-child(3), ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.812 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.818 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(3), ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.823 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.830 INFO - Command request: isVisible[css=#legal > p > a:nth-child(4), ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.840 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.847 INFO - Command request: isElementPresent[css=#legal > p > a:nth-child(4), ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.853 INFO - Got result: OK,true on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:36.861 INFO - Command request: captureEntirePageScreenshotToString[, ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:37.246 INFO - Got result: [base64 encoded PNG] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:37.277 INFO - Command request: getHtmlSource[, ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:37.294 INFO - Got result: [HTML source] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:37.304 INFO - Command request: testComplete[, ] on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:37.304 INFO - Killing Firefox...
     [java] 14:53:37.451 INFO - Got result: OK on session 6c96eb463044491fa1d046cdba30d0ea
     [java] 14:53:37.479 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:53:37.480 INFO - creating new remote session
     [java] 14:53:37.480 INFO - Allocated session afe4f0cfb1574f6bbed1973dc64622fa for http://developer-stage9.mozilla.org, launching...
     [java] 14:53:37.520 INFO - Preparing Firefox profile...
     [java] 14:53:39.687 INFO - Launching Firefox...
     [java] 14:53:40.167 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@41e8e144 at URL: /status)
     [java] 14:53:40.167 INFO - Done: /status
     [java] 14:53:42.117 INFO - Got result: OK,afe4f0cfb1574f6bbed1973dc64622fa on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:42.124 INFO - Command request: setTimeout[180000, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:42.135 INFO - Got result: OK on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:42.141 INFO - Command request: setContext[test_login.TestLogin.test_login, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:42.145 INFO - Got result: OK on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:42.155 INFO - Command request: open[/en-US/profiles/testaccount/, True] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:45.170 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@1fbbc779 at URL: /status)
     [java] 14:53:45.171 INFO - Done: /status
     [java] 14:53:48.175 INFO - Got result: OK on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:48.181 INFO - Command request: waitForPageToLoad[180000, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:48.224 INFO - Got result: OK on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:48.229 INFO - Command request: open[/Special:UserLogin?returntotitle=%2Fen-US%2Fprofiles%2Ftestaccount%2F, True] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:50.174 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@3435ec9 at URL: /status)
     [java] 14:53:50.174 INFO - Done: /status
     [java] 14:53:52.842 INFO - Got result: OK on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:52.848 INFO - Command request: waitForPageToLoad[180000, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:52.863 INFO - Got result: OK on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:52.869 INFO - Command request: type[css=#text-username, testaccount] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:52.880 INFO - Got result: OK on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:52.886 INFO - Command request: type[css=#password-password, theplanet] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:52.893 INFO - Got result: OK on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:52.902 INFO - Command request: click[css=.input-button, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:52.916 INFO - Got result: OK on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:52.922 INFO - Command request: waitForPageToLoad[180000, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.486 INFO - Got result: OK on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.493 INFO - Command request: isVisible[css=.nickname, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.501 INFO - Got result: OK,true on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.509 INFO - Command request: isElementPresent[css=.nickname, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.515 INFO - Got result: OK,true on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.526 INFO - Command request: isVisible[css=.irc, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.534 INFO - Got result: OK,true on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.540 INFO - Command request: isElementPresent[css=.irc, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.546 INFO - Got result: OK,true on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.554 INFO - Command request: isVisible[css=.org, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.565 INFO - Got result: OK,true on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.571 INFO - Command request: isElementPresent[css=.org, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.576 INFO - Got result: OK,true on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.583 INFO - Command request: isVisible[css=.title, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.590 INFO - Got result: OK,true on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.596 INFO - Command request: isElementPresent[css=.title, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:54.602 INFO - Got result: OK,true on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:53:55.177 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@4413515e at URL: /status)
     [java] 14:53:55.177 INFO - Done: /status
     [java] 14:54:00.180 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@64273f4e at URL: /status)
     [java] 14:54:00.181 INFO - Done: /status
     [java] 14:54:05.184 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@5aacc14 at URL: /status)
     [java] 14:54:05.184 INFO - Done: /status
     [java] 14:54:10.187 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@617d7c7f at URL: /status)
     [java] 14:54:10.187 INFO - Done: /status
     [java] 14:54:15.190 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@4453d3cf at URL: /status)
     [java] 14:54:15.191 INFO - Done: /status
     [java] 14:54:20.193 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@58ee21f5 at URL: /status)
     [java] 14:54:20.194 INFO - Done: /status
     [java] 14:54:25.197 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6a6014f7 at URL: /status)
     [java] 14:54:25.197 INFO - Done: /status
     [java] 14:54:30.200 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6dabbec4 at URL: /status)
     [java] 14:54:30.200 INFO - Done: /status
     [java] 14:54:35.204 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6e2c03ff at URL: /status)
     [java] 14:54:35.204 INFO - Done: /status
     [java] 14:54:40.207 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@5ff6de1 at URL: /status)
     [java] 14:54:40.207 INFO - Done: /status
     [java] 14:54:45.210 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6f3b625b at URL: /status)
     [java] 14:54:45.210 INFO - Done: /status
     [java] 14:54:50.213 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@21e3cc77 at URL: /status)
     [java] 14:54:50.214 INFO - Done: /status
     [java] 14:54:55.217 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@63b5a40a at URL: /status)
     [java] 14:54:55.217 INFO - Done: /status
     [java] 14:55:00.220 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@52a34783 at URL: /status)
     [java] 14:55:00.220 INFO - Done: /status
     [java] 14:55:05.223 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@4c4ab84c at URL: /status)
     [java] 14:55:05.224 INFO - Done: /status
     [java] 14:55:10.227 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@19a9bea3 at URL: /status)
     [java] 14:55:10.227 INFO - Done: /status
     [java] 14:55:15.230 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@2d9f90e3 at URL: /status)
     [java] 14:55:15.230 INFO - Done: /status
     [java] 14:55:20.233 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6dcd2197 at URL: /status)
     [java] 14:55:20.234 INFO - Done: /status
     [java] 14:55:25.237 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6a643edd at URL: /status)
     [java] 14:55:25.237 INFO - Done: /status
     [java] 14:55:30.240 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@4959d87f at URL: /status)
     [java] 14:55:30.240 INFO - Done: /status
     [java] 14:55:35.243 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@5c71949b at URL: /status)
     [java] 14:55:35.243 INFO - Done: /status
     [java] 14:55:40.247 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@3852eef4 at URL: /status)
     [java] 14:55:40.247 INFO - Done: /status
     [java] 14:55:45.250 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@5796de29 at URL: /status)
     [java] 14:55:45.250 INFO - Done: /status
     [java] 14:55:50.253 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@7527e2ee at URL: /status)
     [java] 14:55:50.253 INFO - Done: /status
     [java] 14:55:55.256 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@76539f0d at URL: /status)
     [java] 14:55:55.257 INFO - Done: /status
     [java] 14:56:00.260 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@2b302b69 at URL: /status)
     [java] 14:56:00.260 INFO - Done: /status
     [java] 14:56:05.263 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@71a2f5b1 at URL: /status)
     [java] 14:56:05.263 INFO - Done: /status
     [java] 14:56:10.266 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@66fbf51d at URL: /status)
     [java] 14:56:10.267 INFO - Done: /status
     [java] 14:56:15.270 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@79ce00b4 at URL: /status)
     [java] 14:56:15.270 INFO - Done: /status
     [java] 14:56:20.273 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@3d950e0a at URL: /status)
     [java] 14:56:20.273 INFO - Done: /status
     [java] 14:56:25.276 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@22f62eba at URL: /status)
     [java] 14:56:25.276 INFO - Done: /status
     [java] 14:56:30.279 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@646d6aa0 at URL: /status)
     [java] 14:56:30.279 INFO - Done: /status
     [java] 14:56:35.283 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@41f6321 at URL: /status)
     [java] 14:56:35.283 INFO - Done: /status
     [java] 14:56:40.286 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@6c229ed4 at URL: /status)
     [java] 14:56:40.286 INFO - Done: /status
     [java] 14:56:45.289 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@3804dd1b at URL: /status)
     [java] 14:56:45.290 INFO - Done: /status
     [java] 14:56:50.293 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@629ca1fb at URL: /status)
     [java] 14:56:50.293 INFO - Done: /status
     [java] 14:56:55.296 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@76f1fad1 at URL: /status)
     [java] 14:56:55.296 INFO - Done: /status
     [java] 14:56:59.471 INFO - Command request: testComplete[, ] on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:56:59.471 INFO - Killing Firefox...
     [java] 14:56:59.536 INFO - Got result: OK on session afe4f0cfb1574f6bbed1973dc64622fa
     [java] 14:56:59.540 INFO - Command request: getNewBrowserSession[*firefox /Applications/Firefox 7.app/Contents/MacOS/firefox-bin, http://developer-stage9.mozilla.org, ] on session null
     [java] 14:56:59.540 INFO - creating new remote session
     [java] 14:56:59.541 INFO - Allocated session 9aa7070bf3ae48c9b524828966ce18a3 for http://developer-stage9.mozilla.org, launching...
     [java] 14:56:59.581 INFO - Preparing Firefox profile...
     [java] 14:57:00.300 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@3160e069 at URL: /status)
     [java] 14:57:00.300 INFO - Done: /status
     [java] 14:57:02.084 INFO - Launching Firefox...
     [java] 14:57:04.539 INFO - Got result: OK,9aa7070bf3ae48c9b524828966ce18a3 on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:04.551 INFO - Command request: setTimeout[180000, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:04.563 INFO - Got result: OK on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:04.569 INFO - Command request: setContext[test_learn_page.TestLearnPage.test_page_elements_are_visible, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:04.574 INFO - Got result: OK on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:04.585 INFO - Command request: open[/learn, True] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:05.304 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@78a974c7 at URL: /status)
     [java] 14:57:05.304 INFO - Done: /status
     [java] 14:57:10.307 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@1a3526cf at URL: /status)
     [java] 14:57:10.308 INFO - Done: /status
     [java] 14:57:15.311 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@1b50f0a7 at URL: /status)
     [java] 14:57:15.311 INFO - Done: /status
     [java] 14:57:20.314 INFO - Executing: org.openqa.selenium.remote.server.handler.Status@2cea3932 at URL: /status)
     [java] 14:57:20.314 INFO - Done: /status
     [java] 14:57:21.882 INFO - Got result: OK on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.889 INFO - Command request: waitForPageToLoad[180000, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.893 INFO - Got result: OK on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.900 INFO - Command request: isVisible[css=.wrap>.page-title, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.906 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.913 INFO - Command request: isElementPresent[css=.wrap>.page-title, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.922 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.929 INFO - Command request: isVisible[css=#sub-html>a>h2, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.936 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.943 INFO - Command request: isElementPresent[css=#sub-html>a>h2, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.948 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.954 INFO - Command request: isVisible[css=#sub-css>a>h2, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.962 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.968 INFO - Command request: isElementPresent[css=#sub-css>a>h2, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.973 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.981 INFO - Command request: isVisible[css=#sub-js>a>h2, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.989 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:21.995 INFO - Command request: isElementPresent[css=#sub-js>a>h2, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.004 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.010 INFO - Command request: isVisible[css=#blackboard, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.020 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.027 INFO - Command request: isElementPresent[css=#blackboard, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.032 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.039 INFO - Command request: isVisible[css=#learn-p2pu>p>a>span, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.046 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.052 INFO - Command request: isElementPresent[css=#learn-p2pu>p>a>span, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.058 INFO - Got result: OK,true on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.131 INFO - Command request: captureEntirePageScreenshotToString[, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.511 INFO - Got result: [base64 encoded PNG] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.541 INFO - Command request: getHtmlSource[, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.552 INFO - Got result: [HTML source] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.558 INFO - Command request: testComplete[, ] on session 9aa7070bf3ae48c9b524828966ce18a3
     [java] 14:57:22.558 INFO - Killing Firefox...
     [java] 14:57:22.624 INFO - Got result: OK on session 9aa7070bf3ae48c9b524828966ce18a3
	Building on master Checkout:workspace / /Users/Shared/Jenkins/Home/jobs/mdn.staging/workspace - hudson.remoting.LocalChannel@6f76dd71 Using strategy: Default Last Built Revision: Revision 14384a8d45f03d4f76934cec602b3514cfcd9502 (origin/HEAD, origin/master) Checkout:workspace / /Users/Shared/Jenkins/Home/jobs/mdn.staging/workspace - hudson.remoting.LocalChannel@6f76dd71 Fetching changes from 1 remote Git repository Fetching upstream changes from git://github.com/mozilla/mdn-tests.git Seen branch in repository origin/HEAD Seen branch in repository origin/m Seen branch in repository origin/master Seen branch in repository origin/staging Commencing build of Revision 14384a8d45f03d4f76934cec602b3514cfcd9502 (origin/HEAD, origin/master) Checking out Revision 14384a8d45f03d4f76934cec602b3514cfcd9502 (origin/HEAD, origin/master) Warning : There are multiple branch changesets here [EnvInject] - Injecting as environment variables the properties content 'PATH=.env/bin:/usr/bin:/bin:/usr/sbin:/sbin' [workspace] $ /bin/sh -xe /var/folders/Wp/Wp49uNCTGAq9KGDuyHFZDU+++TI/-Tmp-/hudson1963919258291913138.sh + find results results.xml page.pyc -print0 + xargs -0 rm -v -Rf results/debug/test_dev_derby_TestDevDerbyPage_test_are_footer_links_visible.html results/debug/test_dev_derby_TestDevDerbyPage_test_are_footer_links_visible.png results/debug/test_dev_derby_TestDevDerbyPage_test_are_previous_challenges_present.html results/debug/test_dev_derby_TestDevDerbyPage_test_are_previous_challenges_present.png results/debug/test_dev_derby_TestDevDerbyPage_test_derby_links_visible.html results/debug/test_dev_derby_TestDevDerbyPage_test_derby_links_visible.png results/debug/test_dev_derby_TestDevDerbyPage_test_judge_images_visible.html results/debug/test_dev_derby_TestDevDerbyPage_test_judge_images_visible.png results/debug/test_homepage_TestHomepage_test_demo_image.html results/debug/test_homepage_TestHomepage_test_demo_image.png results/debug/test_homepage_TestHomepage_test_demo_title.html results/debug/test_homepage_TestHomepage_test_demo_title.png results/debug/test_homepage_TestHomepage_test_footer_links.html results/debug/test_homepage_TestHomepage_test_footer_links.png results/debug/test_homepage_TestHomepage_test_header_links.html results/debug/test_homepage_TestHomepage_test_header_links.png results/debug/test_learn_page_TestLearnPage_test_are_footer_links_visible.html results/debug/test_learn_page_TestLearnPage_test_are_footer_links_visible.png results/debug/test_learn_page_TestLearnPage_test_header_links_visible.html results/debug/test_learn_page_TestLearnPage_test_header_links_visible.png results/debug/test_learn_page_TestLearnPage_test_page_elements_are_visible.html results/debug/test_learn_page_TestLearnPage_test_page_elements_are_visible.png results/debug/test_login_TestLogin_test_login.html results/debug/test_login_TestLogin_test_login.png results/debug results/index.html results results.xml page.pyc [workspace] $ /bin/sh -xe /var/folders/Wp/Wp49uNCTGAq9KGDuyHFZDU+++TI/-Tmp-/hudson8089558012655075834.sh + '[' -d .env ']' + echo '> virtualenv exists' > virtualenv exists [workspace] $ /bin/sh -xe /var/folders/Wp/Wp49uNCTGAq9KGDuyHFZDU+++TI/-Tmp-/hudson780757454443661495.sh + pip install -Ur requirements/requirements.txt
	Downloading/unpacking selenium (from -r requirements/requirements.txt (line 4)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fs%2Fselenium%2Fselenium-2.13.1.tar.gz Running setup.py egg_info for package selenium /System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/distutils/dist.py:266: UserWarning: Unknown distribution option: 'src_root' warnings.warn(msg) warning: no files found matching 'docs/api/py/index.rst' Downloading/unpacking pytest (from -r requirements/requirements.txt (line 5)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fp%2Fpytest%2Fpytest-2.2.0.zip Running setup.py egg_info for package pytest Downloading/unpacking pytest-xdist (from -r requirements/requirements.txt (line 6)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fp%2Fpytest-xdist%2Fpytest-xdist-1.7.zip Running setup.py egg_info for package pytest-xdist warning: no previously-included files found matching '.orig' warning: no previously-included files found matching '.rej' warning: no previously-included files matching '.pyc' found under directory 'testing' warning: no previously-included files matching '$py.class' found under directory 'testing' no previously-included directories found matching '.svn' no previously-included directories found matching '.hg' Downloading/unpacking unittestzero (from -r requirements/requirements.txt (line 7)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2FU%2FUnittestZero%2FUnittestZero-0.1.6.tar.gz Running setup.py egg_info for package unittestzero Downloading/unpacking pytest-mozwebqa (from -r requirements/requirements.txt (line 8)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fp%2Fpytest-mozwebqa%2Fpytest-mozwebqa-0.5.tar.gz Running setup.py egg_info for package pytest-mozwebqa Downloading/unpacking rdflib==3.1.0 (from selenium->-r requirements/requirements.txt (line 4)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fr%2Frdflib%2Frdflib-3.1.0.tar.gz Running setup.py egg_info for package rdflib Downloading/unpacking py>=1.4.5 (from pytest->-r requirements/requirements.txt (line 5)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fp%2Fpy%2Fpy-1.4.5.zip Running setup.py egg_info for package py Downloading/unpacking execnet>=1.0.8 (from pytest-xdist->-r requirements/requirements.txt (line 6)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2Fe%2Fexecnet%2Fexecnet-1.0.9.zip Running setup.py egg_info for package execnet no previously-included directories found matching 'doc/_build' warning: no previously-included files found matching '.orig' warning: no previously-included files found matching '.rej' warning: no previously-included files matching '.pyc' found under directory 'execnet' warning: no previously-included files matching '$py.class' found under directory 'execnet' warning: no previously-included files matching '.pyc' found under directory 'testing' warning: no previously-included files matching '$py.class' found under directory 'testing' no previously-included directories found matching '.svn' no previously-included directories found matching '.hg' Downloading/unpacking pyyaml (from pytest-mozwebqa->-r requirements/requirements.txt (line 8)) Using download cache from /Users/daveandpam/.pip_download_cache/http%3A%2F%2Fpypi.python.org%2Fpackages%2Fsource%2FP%2FPyYAML%2FPyYAML-3.10.tar.gz Running setup.py egg_info for package pyyaml Installing collected packages: selenium, pytest, pytest-xdist, unittestzero, pytest-mozwebqa, rdflib, py, execnet, pyyaml Found existing installation: selenium 2.13.1 Uninstalling selenium: Successfully uninstalled selenium Running setup.py install for selenium /System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/distutils/dist.py:266: UserWarning: Unknown distribution option: 'src_root' warnings.warn(msg) warning: no files found matching 'docs/api/py/index.rst' Found existing installation: pytest 2.2.0 Uninstalling pytest: Successfully uninstalled pytest Running setup.py install for pytest Installing py.test script to /Users/Shared/Jenkins/Home/jobs/mdn.staging/workspace/.env/bin Installing py.test-2.6 script to /Users/Shared/Jenkins/Home/jobs/mdn.staging/workspace/.env/bin Found existing installation: pytest-xdist 1.7 Uninstalling pytest-xdist: Successfully uninstalled pytest-xdist Running setup.py install for pytest-xdist warning: no previously-included files found matching '.orig' warning: no previously-included files found matching '.rej' warning: no previously-included files matching '.pyc' found under directory 'testing' warning: no previously-included files matching '$py.class' found under directory 'testing' no previously-included directories found matching '.svn' no previously-included directories found matching '.hg' Found existing installation: UnittestZero 0.1.6 Uninstalling UnittestZero: Successfully uninstalled UnittestZero Running setup.py install for unittestzero Found existing installation: pytest-mozwebqa 0.5 Uninstalling pytest-mozwebqa: Successfully uninstalled pytest-mozwebqa Running setup.py install for pytest-mozwebqa Found existing installation: rdflib 3.1.0 Uninstalling rdflib: Successfully uninstalled rdflib Running setup.py install for rdflib Found existing installation: py 1.4.5 Uninstalling py: Successfully uninstalled py Running setup.py install for py Found existing installation: execnet 1.0.9 Uninstalling execnet: Successfully uninstalled execnet Running setup.py install for execnet no previously-included directories found matching 'doc/_build' warning: no previously-included files found matching '.orig' warning: no previously-included files found matching '.rej' warning: no previously-included files matching '.pyc' found under directory 'execnet' warning: no previously-included files matching '$py.class' found under directory 'execnet' warning: no previously-included files matching '.pyc' found under directory 'testing' warning: no previously-included files matching '$py.class' found under directory 'testing' no previously-included directories found matching '.svn' no previously-included directories found matching '.hg' Found existing installation: PyYAML 3.10 Uninstalling PyYAML: Successfully uninstalled PyYAML Running setup.py install for pyyaml checking if libyaml is compilable gcc-4.2 -fno-strict-aliasing -fno-common -dynamic -DNDEBUG -g -fwrapv -Os -Wall -Wstrict-prototypes -DENABLE_DTRACE -arch i386 -arch ppc -arch x86_64 -pipe -I/System/Library/Frameworks/Python.framework/Versions/2.6/include/python2.6 -c build/temp.macosx-10.6-universal-2.6/check_libyaml.c -o build/temp.macosx-10.6-universal-2.6/check_libyaml.o build/temp.macosx-10.6-universal-2.6/check_libyaml.c:2:18: error: yaml.h: No such file or directory build/temp.macosx-10.6-universal-2.6/check_libyaml.c: In function 'main': build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: 'yaml_parser_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: (Each undeclared identifier is reported only once build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: for each function it appears in.) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: expected ';' before 'parser' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: 'yaml_emitter_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: expected ';' before 'emitter' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: warning: implicit declaration of function 'yaml_parser_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: error: 'parser' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:9: warning: implicit declaration of function 'yaml_parser_delete' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: warning: implicit declaration of function 'yaml_emitter_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: error: 'emitter' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:12: warning: implicit declaration of function 'yaml_emitter_delete' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:2:18: error: yaml.h: No such file or directory build/temp.macosx-10.6-universal-2.6/check_libyaml.c: In function 'main': build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: 'yaml_parser_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: (Each undeclared identifier is reported only once build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: for each function it appears in.) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: expected ';' before 'parser' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: 'yaml_emitter_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: expected ';' before 'emitter' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: warning: implicit declaration of function 'yaml_parser_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: error: 'parser' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:9: warning: implicit declaration of function 'yaml_parser_delete' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: warning: implicit declaration of function 'yaml_emitter_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: error: 'emitter' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:12: warning: implicit declaration of function 'yaml_emitter_delete' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:2:18: error: yaml.h: No such file or directory build/temp.macosx-10.6-universal-2.6/check_libyaml.c: In function 'main': build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: 'yaml_parser_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: (Each undeclared identifier is reported only once build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: for each function it appears in.) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:5: error: expected ';' before 'parser' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: 'yaml_emitter_t' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:6: error: expected ';' before 'emitter' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: warning: implicit declaration of function 'yaml_parser_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:8: error: 'parser' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:9: warning: implicit declaration of function 'yaml_parser_delete' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: warning: implicit declaration of function 'yaml_emitter_initialize' build/temp.macosx-10.6-universal-2.6/check_libyaml.c:11: error: 'emitter' undeclared (first use in this function) build/temp.macosx-10.6-universal-2.6/check_libyaml.c:12: warning: implicit declaration of function 'yaml_emitter_delete' lipo: can't open input file: /var/folders/Wp/Wp49uNCTGAq9KGDuyHFZDU+++TI/-Tmp-//cc3xmG6o.out (No such file or directory) libyaml is not found or a compiler error: forcing --without-libyaml (if libyaml is installed correctly, you may need to specify the option --include-dirs or uncomment and modify the parameter include_dirs in setup.cfg) Successfully installed selenium pytest pytest-xdist unittestzero pytest-mozwebqa rdflib py execnet pyyaml Cleaning up... [workspace] $ /bin/sh -xe /var/folders/Wp/Wp49uNCTGAq9KGDuyHFZDU+++TI/-Tmp-/hudson7396805463204623585.sh + py.test -n 2 -r fsxX --baseurl=http://developer-stage9.mozilla.org --api=rc '--environment=Firefox 7 on Mac OS X' --timeout=180000 --junitxml=results.xml --credentials=/Users/daveandpam/workspace/webqa-credentials/mdn.yaml --junitxml=results.xml
	============================= test session starts ============================== platform darwin -- Python 2.6.1 -- pytest-2.2.0 gw0 I / gw1 I
	gw0 [12] / gw1 [12] scheduling tests via LoadScheduling
	x...........E ==================================== ERRORS ==================================== __________________ ERROR at teardown of TestLogin.test_login ___________________ [gw0] darwin -- Python 2.6.1 /Users/Shared/Jenkins/Home/jobs/mdn.staging/workspace/.env/bin/python item = <Function 'test_login'> def pytest_runtest_teardown(item): if hasattr(TestSetup, 'selenium') and TestSetup.selenium and not 'skip_selenium' in item.keywords: > _capture_debug(item) .env/lib/python2.6/site-packages/mozwebqa/mozwebqa.py:107: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ item = <Function 'test_login'> def _capture_debug(item): filename = _debug_path(item) _capture_screenshot(item, filename) > _capture_html(item, filename) .env/lib/python2.6/site-packages/mozwebqa/mozwebqa.py:389: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ item = <Function 'test_login'> filename = 'results/debug/test_login_TestLogin_test_login' def _capture_html(item, filename): f = open("%s.html" % filename, 'wb') if item.api.upper() == 'WEBDRIVER': f.write(TestSetup.selenium.page_source.encode('utf-8')) else: > f.write(TestSetup.selenium.get_html_source().encode('utf-8')) .env/lib/python2.6/site-packages/mozwebqa/mozwebqa.py:436: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = <selenium.selenium.selenium object at 0x104042a10> def get_html_source(self): """ Returns the entire HTML source between the opening and closing "html" tags. """ > return self.get_string("getHtmlSource", []) def set_cursor_position(self,locator,position): .env/lib/python2.6/site-packages/selenium/selenium.py:1538: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = <selenium.selenium.selenium object at 0x104042a10> verb = 'getHtmlSource', args = [] def get_string(self, verb, args): > result = self.do_command(verb, args) .env/lib/python2.6/site-packages/selenium/selenium.py:220: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = <selenium.selenium.selenium object at 0x104042a10> verb = 'getHtmlSource', args = [] def do_command(self, verb, args): conn = httplib.HTTPConnection(self.host, self.port) try: body = u'cmd=' + urllib.quote_plus(unicode(verb).encode('utf-8')) for i in range(len(args)): body += '&' + unicode(i+1) + '=' + \ urllib.quote_plus(unicode(args[i]).encode('utf-8')) if (None != self.sessionId): body += "&sessionId=" + unicode(self.sessionId) headers = { "Content-Type": "application/x-www-form-urlencoded; charset=utf-8" } conn.request("POST", "/selenium-server/driver/", body, headers) response = conn.getresponse() data = unicode(response.read(), "UTF-8") if (not data.startswith('OK')): > raise Exception, data E Exception: <html> E <head> E <title>Error 500 org.openqa.grid.common.exception.GridException: Session [afe4f0cfb1574f6bbed1973dc64622fa] not available - [ext. key 9aa7070bf3ae48c9b524828966ce18a3]</title> E </head> E <body> E <h2>HTTP ERROR: 500</h2><pre>org.openqa.grid.common.exception.GridException: Session [afe4f0cfb1574f6bbed1973dc64622fa] not available - [ext. key 9aa7070bf3ae48c9b524828966ce18a3]</pre> E <p>RequestURI=/selenium-server/driver/</p> E <p><i><small><a href="http://jetty.mortbay.org">Powered by Jetty://</a></small></i></p> E E E E E E E E E E E E E E E E E E E E E </body> E </html> .env/lib/python2.6/site-packages/selenium/selenium.py:214: Exception ----------------------- generated xml file: results.xml ------------------------ =========================== short test summary info ============================ XFAIL test_dev_derby.py::TestDevDerbyPage::()::test_derby_links_visible No derby winners on production yet =============== 11 passed, 1 xfailed, 1 error in 376.95 seconds ================ Build step 'Execute shell' marked build as failure Archiving artifacts Recording test results Finished: FAILURE
	launch-hub:
	[java] Nov 28, 2011 2:49:41 PM org.openqa.grid.selenium.GridLauncher main
	[java] INFO: Launching a selenium grid server
	[java] Nov 28, 2011 2:49:44 PM org.openqa.jetty.http.HttpServer doStart
	[java] INFO: Version Jetty/5.1.x
	[java] Nov 28, 2011 2:49:44 PM org.openqa.jetty.util.FileResource <clinit>
	[java] INFO: Checking Resource aliases
	[java] Nov 28, 2011 2:49:46 PM org.openqa.jetty.util.Container start
	[java] INFO: Started org.openqa.jetty.jetty.servlet.WebApplicationHandler@f284fd4
	[java] Nov 28, 2011 2:49:46 PM org.openqa.jetty.util.Container start
	[java] INFO: Started WebApplicationContext[/,/]
	[java] Nov 28, 2011 2:49:46 PM org.openqa.jetty.http.SocketListener start
	[java] INFO: Started SocketListener on 0.0.0.0:4444
	[java] Nov 28, 2011 2:49:46 PM org.openqa.jetty.util.Container start
	[java] INFO: Started org.openqa.jetty.jetty.Server@32955cd5
	[java] Nov 28, 2011 2:56:59 PM org.openqa.grid.internal.RemoteProxy$CleanUpThread run
	[java] WARNING: session ext. key afe4f0cfb1574f6bbed1973dc64622fa has TIMED OUT and will be released
	[java] Nov 28, 2011 2:57:22 PM org.openqa.grid.internal.ActiveTestSessions getExistingSession
	[java] WARNING: Client requested session afe4f0cfb1574f6bbed1973dc64622fa that was terminated due to TIMEOUT
	[java] Nov 28, 2011 2:57:22 PM org.openqa.grid.internal.ActiveTestSessions getExistingSession
	[java] WARNING: Client requested session afe4f0cfb1574f6bbed1973dc64622fa that was terminated due to TIMEOUT