builder: fx-team_ubuntu64_hw_test-other-e10s slave: talos-linux64-ix-053 starttime: 1448312284.51 results: success (0) buildid: 20151120090830 builduid: 9b3dc1bd24354a9aacec687cccc2ce8f revision: a0db720c980e3fbacf92c03566e8ffea5fdefd2d ========= Started set props: master (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.510010) ========= master: http://buildbot-master105.bb.releng.scl3.mozilla.com:8201/ ========= Finished set props: master (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.510682) ========= ========= Started set props: basedir (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.511139) ========= bash -c pwd in dir /builds/slave/test/. (timeout 1200 secs) watching logfiles {} argv: ['bash', '-c', 'pwd'] environment: DISPLAY=:0 HOME=/home/cltbld LANG=en_US.UTF-8 LANGUAGE=en_US:en LOGNAME=cltbld MAIL=/var/mail/cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript NO_EM_RESTART=1 PATH=/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games PWD=/builds/slave/test SHELL=/bin/bash SHLVL=1 TERM=linux TMOUT=86400 USER=cltbld XDG_SESSION_COOKIE=919420d7ee4ef147bef0346300000385-1448312283.868710-972446830 XPCOM_DEBUG_BREAK=warn _=/tools/buildbot/bin/python using PTY: False /builds/slave/test program finished with exit code 0 elapsedTime=0.006469 basedir: '/builds/slave/test' ========= master_lag: 0.02 ========= ========= Finished set props: basedir (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.541766) ========= ========= Started downloading to buildprops.json (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.542069) ========= ========= Finished downloading to buildprops.json (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.556297) ========= ========= Started 'rm -rf ...' (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.556730) ========= rm -rf properties in dir /builds/slave/test/. (timeout 1200 secs) watching logfiles {} argv: ['rm', '-rf', 'properties'] environment: DISPLAY=:0 HOME=/home/cltbld LANG=en_US.UTF-8 LANGUAGE=en_US:en LOGNAME=cltbld MAIL=/var/mail/cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript NO_EM_RESTART=1 PATH=/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games PWD=/builds/slave/test SHELL=/bin/bash SHLVL=1 TERM=linux TMOUT=86400 USER=cltbld XDG_SESSION_COOKIE=919420d7ee4ef147bef0346300000385-1448312283.868710-972446830 XPCOM_DEBUG_BREAK=warn _=/tools/buildbot/bin/python using PTY: False program finished with exit code 0 elapsedTime=0.004591 ========= master_lag: 0.05 ========= ========= Finished 'rm -rf ...' (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.606926) ========= ========= Started set props: script_repo_url (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.607260) ========= script_repo_url: https://hg.mozilla.org/build/mozharness ========= Finished set props: script_repo_url (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.607642) ========= ========= Started 'bash -c ...' (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.607917) ========= bash -c 'wget -Oarchiver_client.py --no-check-certificate --tries=10 --waitretry=3 https://hg.mozilla.org/build/tools/raw-file/default/buildfarm/utils/archiver_client.py' in dir /builds/slave/test/. (timeout 1200 secs) watching logfiles {} argv: ['bash', '-c', 'wget -Oarchiver_client.py --no-check-certificate --tries=10 --waitretry=3 https://hg.mozilla.org/build/tools/raw-file/default/buildfarm/utils/archiver_client.py'] environment: DISPLAY=:0 HOME=/home/cltbld LANG=en_US.UTF-8 LANGUAGE=en_US:en LOGNAME=cltbld MAIL=/var/mail/cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript NO_EM_RESTART=1 PATH=/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games PWD=/builds/slave/test SHELL=/bin/bash SHLVL=1 TERM=linux TMOUT=86400 USER=cltbld XDG_SESSION_COOKIE=919420d7ee4ef147bef0346300000385-1448312283.868710-972446830 XPCOM_DEBUG_BREAK=warn _=/tools/buildbot/bin/python using PTY: False --2015-11-23 12:58:04-- https://hg.mozilla.org/build/tools/raw-file/default/buildfarm/utils/archiver_client.py Resolving hg.mozilla.org (hg.mozilla.org)... 63.245.215.25, 63.245.215.102 Connecting to hg.mozilla.org (hg.mozilla.org)|63.245.215.25|:443... connected. HTTP request sent, awaiting response... 200 Script output follows Length: 12141 (12K) [text/x-python] Saving to: `archiver_client.py' 0K .......... . 100% 8.24M=0.001s 2015-11-23 12:58:04 (8.24 MB/s) - `archiver_client.py' saved [12141/12141] program finished with exit code 0 elapsedTime=0.095794 ========= master_lag: 0.01 ========= ========= Finished 'bash -c ...' (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.716197) ========= ========= Started 'rm -rf ...' (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.716551) ========= rm -rf scripts in dir /builds/slave/test/. (timeout 1200 secs) watching logfiles {} argv: ['rm', '-rf', 'scripts'] environment: DISPLAY=:0 HOME=/home/cltbld LANG=en_US.UTF-8 LANGUAGE=en_US:en LOGNAME=cltbld MAIL=/var/mail/cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript NO_EM_RESTART=1 PATH=/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games PWD=/builds/slave/test SHELL=/bin/bash SHLVL=1 TERM=linux TMOUT=86400 USER=cltbld XDG_SESSION_COOKIE=919420d7ee4ef147bef0346300000385-1448312283.868710-972446830 XPCOM_DEBUG_BREAK=warn _=/tools/buildbot/bin/python using PTY: False program finished with exit code 0 elapsedTime=0.022594 ========= master_lag: 0.03 ========= ========= Finished 'rm -rf ...' (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.766318) ========= ========= Started 'bash -c ...' (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:04.766681) ========= bash -c 'python archiver_client.py mozharness --repo integration/fx-team --rev a0db720c980e3fbacf92c03566e8ffea5fdefd2d --destination scripts --debug' in dir /builds/slave/test/. (timeout 1200 secs) watching logfiles {} argv: ['bash', '-c', u'python archiver_client.py mozharness --repo integration/fx-team --rev a0db720c980e3fbacf92c03566e8ffea5fdefd2d --destination scripts --debug'] environment: DISPLAY=:0 HOME=/home/cltbld LANG=en_US.UTF-8 LANGUAGE=en_US:en LOGNAME=cltbld MAIL=/var/mail/cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript NO_EM_RESTART=1 PATH=/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games PWD=/builds/slave/test SHELL=/bin/bash SHLVL=1 TERM=linux TMOUT=86400 USER=cltbld XDG_SESSION_COOKIE=919420d7ee4ef147bef0346300000385-1448312283.868710-972446830 XPCOM_DEBUG_BREAK=warn _=/tools/buildbot/bin/python using PTY: False 2015-11-23 12:58:04,957 truncating revision to first 12 chars 2015-11-23 12:58:04,958 Setting DEBUG logging. 2015-11-23 12:58:04,958 attempt 1/10 2015-11-23 12:58:04,958 Getting archive location from https://api.pub.build.mozilla.org/archiver/hgmo/integration/fx-team/a0db720c980e?&preferred_region=us-west-2&suffix=tar.gz&subdir=testing/mozharness 2015-11-23 12:58:05,464 unpacking tar archive at: fx-team-a0db720c980e/testing/mozharness/ program finished with exit code 0 elapsedTime=0.799209 ========= master_lag: 0.02 ========= ========= Finished 'bash -c ...' (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:05.581025) ========= ========= Started downloading to oauth.txt (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:05.581775) ========= ========= Finished downloading to oauth.txt (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:05.594108) ========= ========= Started tinderboxprint_script_revlink (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:05.594674) ========= TinderboxPrint: script_revlink: https://hg.mozilla.org/build/mozharness/rev/production ========= Finished tinderboxprint_script_revlink (results: 0, elapsed: 0 secs) (at 2015-11-23 12:58:05.595347) ========= ========= Started '/tools/buildbot/bin/python scripts/scripts/talos_script.py ...' (results: 0, elapsed: 5 mins, 51 secs) (at 2015-11-23 12:58:05.595822) ========= /tools/buildbot/bin/python scripts/scripts/talos_script.py --suite other-e10s --add-option --webServer,localhost --branch-name Fx-Team-Non-PGO --system-bits 64 --cfg talos/linux_config.py --download-symbols ondemand --use-talos-json --blob-upload-branch Fx-Team-Non-PGO in dir /builds/slave/test/. (timeout 3600 secs) (maxTime 7200 secs) watching logfiles {} argv: ['/tools/buildbot/bin/python', 'scripts/scripts/talos_script.py', '--suite', 'other-e10s', '--add-option', '--webServer,localhost', '--branch-name', 'Fx-Team-Non-PGO', '--system-bits', '64', '--cfg', 'talos/linux_config.py', '--download-symbols', 'ondemand', '--use-talos-json', '--blob-upload-branch', 'Fx-Team-Non-PGO'] environment: DISPLAY=:0 HOME=/home/cltbld LANG=en_US.UTF-8 LANGUAGE=en_US:en LOGNAME=cltbld MAIL=/var/mail/cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript NO_EM_RESTART=1 PATH=/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games PROPERTIES_FILE=/builds/slave/test/buildprops.json PWD=/builds/slave/test SHELL=/bin/bash SHLVL=1 TERM=linux TMOUT=86400 USER=cltbld XDG_SESSION_COOKIE=919420d7ee4ef147bef0346300000385-1448312283.868710-972446830 XPCOM_DEBUG_BREAK=warn _=/tools/buildbot/bin/python using PTY: False 12:58:05 INFO - MultiFileLogger online at 20151123 12:58:05 in /builds/slave/test 12:58:05 INFO - Run as scripts/scripts/talos_script.py --suite other-e10s --add-option --webServer,localhost --branch-name Fx-Team-Non-PGO --system-bits 64 --cfg talos/linux_config.py --download-symbols ondemand --use-talos-json --blob-upload-branch Fx-Team-Non-PGO 12:58:05 INFO - Dumping config to /builds/slave/test/logs/localconfig.json. 12:58:05 INFO - {'append_to_log': False, 12:58:05 INFO - 'base_work_dir': '/builds/slave/test', 12:58:05 INFO - 'blob_upload_branch': 'Fx-Team-Non-PGO', 12:58:05 INFO - 'blob_uploader_auth_file': '/builds/slave/test/oauth.txt', 12:58:05 INFO - 'branch': 'Fx-Team-Non-PGO', 12:58:05 INFO - 'buildbot_json_path': 'buildprops.json', 12:58:05 INFO - 'config_files': ('talos/linux_config.py',), 12:58:05 INFO - 'default_actions': ('clobber', 12:58:05 INFO - 'read-buildbot-config', 12:58:05 INFO - 'download-and-extract', 12:58:05 INFO - 'populate-webroot', 12:58:05 INFO - 'create-virtualenv', 12:58:05 INFO - 'install', 12:58:05 INFO - 'run-tests'), 12:58:05 INFO - 'default_blob_upload_servers': ('https://blobupload.elasticbeanstalk.com',), 12:58:05 INFO - 'download_minidump_stackwalk': True, 12:58:05 INFO - 'download_symbols': 'ondemand', 12:58:05 INFO - 'exes': {'python': '/tools/buildbot/bin/python', 12:58:05 INFO - 'tooltool.py': '/tools/tooltool.py', 12:58:05 INFO - 'virtualenv': ('/tools/buildbot/bin/python', 12:58:05 INFO - '/tools/misc-python/virtualenv.py')}, 12:58:05 INFO - 'find_links': ('http://pypi.pvt.build.mozilla.org/pub', 12:58:05 INFO - 'http://pypi.pub.build.mozilla.org/pub'), 12:58:05 INFO - 'installer_path': 'installer.exe', 12:58:05 INFO - 'log_level': 'info', 12:58:05 INFO - 'log_name': 'talos', 12:58:05 INFO - 'log_to_console': True, 12:58:05 INFO - 'minidump_stackwalk_path': 'linux64-minidump_stackwalk', 12:58:05 INFO - 'minidump_tooltool_manifest_path': 'config/tooltool-manifests/linux64/releng.manifest', 12:58:05 INFO - 'opt_config_files': (), 12:58:05 INFO - 'pip_index': False, 12:58:05 INFO - 'sps_profile': False, 12:58:05 INFO - 'sps_profile_interval': 0, 12:58:05 INFO - 'suite': 'other-e10s', 12:58:05 INFO - 'system_bits': '64', 12:58:05 INFO - 'talos_extra_options': ('--webServer', 'localhost'), 12:58:05 INFO - 'title': 'talos-linux64-ix-053', 12:58:05 INFO - 'tooltool_cache': '/builds/tooltool_cache', 12:58:05 INFO - 'use_talos_json': True, 12:58:05 INFO - 'virtualenv_path': '/builds/slave/test/build/venv', 12:58:05 INFO - 'volatile_config': {'actions': None, 'add_actions': None, 'no_actions': None}, 12:58:05 INFO - 'work_dir': 'build'} 12:58:05 INFO - ##### 12:58:05 INFO - ##### Running clobber step. 12:58:05 INFO - ##### 12:58:05 INFO - Running pre-action listener: _resource_record_pre_action 12:58:05 INFO - Running main action method: clobber 12:58:05 INFO - rmtree: /builds/slave/test/build 12:58:05 INFO - retry: Calling rmtree with args: ('/builds/slave/test/build',), kwargs: {}, attempt #1 12:58:06 INFO - Running post-action listener: _resource_record_post_action 12:58:06 INFO - ##### 12:58:06 INFO - ##### Running read-buildbot-config step. 12:58:06 INFO - ##### 12:58:06 INFO - Running pre-action listener: _resource_record_pre_action 12:58:06 INFO - Running main action method: read_buildbot_config 12:58:06 INFO - Using buildbot properties: 12:58:06 INFO - { 12:58:06 INFO - "properties": { 12:58:06 INFO - "buildnumber": 328, 12:58:06 INFO - "product": "firefox", 12:58:06 INFO - "script_repo_revision": "production", 12:58:06 INFO - "builddir": "fx-team_ubuntu64_hw_test-other-e10s", 12:58:06 INFO - "repository": "", 12:58:06 INFO - "buildername": "Ubuntu HW 12.04 x64 fx-team talos other-e10s", 12:58:06 INFO - "buildid": "20151120090830", 12:58:06 INFO - "slavename": "talos-linux64-ix-053", 12:58:06 INFO - "pgo_build": "False", 12:58:06 INFO - "basedir": "/builds/slave/test", 12:58:06 INFO - "project": "", 12:58:06 INFO - "platform": "ubuntu64_hw", 12:58:06 INFO - "master": "http://buildbot-master105.bb.releng.scl3.mozilla.com:8201/", 12:58:06 INFO - "slavebuilddir": "test", 12:58:06 INFO - "scheduler": "tests-fx-team-linux64-talos", 12:58:06 INFO - "branch": "fx-team", 12:58:06 INFO - "repo_path": "integration/fx-team", 12:58:06 INFO - "stage_platform": "linux64", 12:58:06 INFO - "builduid": "9b3dc1bd24354a9aacec687cccc2ce8f", 12:58:06 INFO - "revision": "a0db720c980e3fbacf92c03566e8ffea5fdefd2d" 12:58:06 INFO - }, 12:58:06 INFO - "sourcestamp": { 12:58:06 INFO - "repository": "", 12:58:06 INFO - "hasPatch": false, 12:58:06 INFO - "project": "", 12:58:06 INFO - "branch": "fx-team-linux64-talos", 12:58:06 INFO - "changes": [ 12:58:06 INFO - { 12:58:06 INFO - "category": null, 12:58:06 INFO - "files": [ 12:58:06 INFO - { 12:58:06 INFO - "url": null, 12:58:06 INFO - "name": "https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2" 12:58:06 INFO - } 12:58:06 INFO - ], 12:58:06 INFO - "repository": "", 12:58:06 INFO - "rev": "a0db720c980e3fbacf92c03566e8ffea5fdefd2d", 12:58:06 INFO - "who": "dtownsend@mozilla.com", 12:58:06 INFO - "when": 1448041494, 12:58:06 INFO - "number": 6689725, 12:58:06 INFO - "comments": "Bug 1146926: Allow attaching a worker to a CPOW window without invoking CPOW operations. r=gabor\n\nBy sending the CPOW to the child processes the one that owns it will create the\nchild worker and then send back the url of the window to set up the parent\nside of the worker.\n\nThere are two breaking changes here. Workers invoked in this way no longer\nattach synchronously. We no longer pass the window through the attach event.", 12:58:06 INFO - "project": "", 12:58:06 INFO - "at": "Fri 20 Nov 2015 09:44:54", 12:58:06 INFO - "branch": "fx-team-linux64-talos", 12:58:06 INFO - "revlink": "", 12:58:06 INFO - "properties": [ 12:58:06 INFO - [ 12:58:06 INFO - "buildid", 12:58:06 INFO - "20151120090830", 12:58:06 INFO - "Change" 12:58:06 INFO - ], 12:58:06 INFO - [ 12:58:06 INFO - "builduid", 12:58:06 INFO - "9b3dc1bd24354a9aacec687cccc2ce8f", 12:58:06 INFO - "Change" 12:58:06 INFO - ], 12:58:06 INFO - [ 12:58:06 INFO - "pgo_build", 12:58:06 INFO - "False", 12:58:06 INFO - "Change" 12:58:06 INFO - ] 12:58:06 INFO - ], 12:58:06 INFO - "revision": "a0db720c980e3fbacf92c03566e8ffea5fdefd2d" 12:58:06 INFO - } 12:58:06 INFO - ], 12:58:06 INFO - "revision": "a0db720c980e3fbacf92c03566e8ffea5fdefd2d" 12:58:06 INFO - } 12:58:06 INFO - } 12:58:06 INFO - Found installer url https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2. 12:58:06 INFO - Running post-action listener: _resource_record_post_action 12:58:06 INFO - ##### 12:58:06 INFO - ##### Running download-and-extract step. 12:58:06 INFO - ##### 12:58:06 INFO - Running pre-action listener: _resource_record_pre_action 12:58:06 INFO - Running main action method: download_and_extract 12:58:06 INFO - mkdir: /builds/slave/test/build/tests 12:58:06 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:06 INFO - https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/test_packages.json matches https://queue.taskcluster.net 12:58:06 INFO - URL Candidate: http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/test_packages.json 12:58:06 INFO - trying http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/test_packages.json 12:58:06 INFO - Downloading http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/test_packages.json to /builds/slave/test/build/test_packages.json 12:58:06 INFO - retry: Calling _download_file with args: (), kwargs: {'url': 'http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/test_packages.json', 'file_name': '/builds/slave/test/build/test_packages.json'}, attempt #1 12:58:06 INFO - Downloaded 1302 bytes. 12:58:06 INFO - Reading from file /builds/slave/test/build/test_packages.json 12:58:06 INFO - Using the following test package requirements: 12:58:06 INFO - {u'common': [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip'], 12:58:06 INFO - u'cppunittest': [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip', 12:58:06 INFO - u'firefox-45.0a1.en-US.linux-x86_64.cppunittest.tests.zip'], 12:58:06 INFO - u'jittest': [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip', 12:58:06 INFO - u'jsshell-linux-x86_64.zip'], 12:58:06 INFO - u'mochitest': [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip', 12:58:06 INFO - u'firefox-45.0a1.en-US.linux-x86_64.mochitest.tests.zip'], 12:58:06 INFO - u'mozbase': [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip'], 12:58:06 INFO - u'reftest': [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip', 12:58:06 INFO - u'firefox-45.0a1.en-US.linux-x86_64.reftest.tests.zip'], 12:58:06 INFO - u'talos': [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip', 12:58:06 INFO - u'firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip'], 12:58:06 INFO - u'web-platform': [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip', 12:58:06 INFO - u'firefox-45.0a1.en-US.linux-x86_64.web-platform.tests.zip'], 12:58:06 INFO - u'webapprt': [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip'], 12:58:06 INFO - u'xpcshell': [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip', 12:58:06 INFO - u'firefox-45.0a1.en-US.linux-x86_64.xpcshell.tests.zip']} 12:58:06 INFO - Downloading packages: [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip'] for test suite category: common 12:58:06 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:06 INFO - https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip matches https://queue.taskcluster.net 12:58:06 INFO - URL Candidate: http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip 12:58:06 INFO - trying http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip 12:58:06 INFO - Downloading http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip to /builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip 12:58:06 INFO - retry: Calling _download_file with args: (), kwargs: {'url': u'http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip', 'file_name': u'/builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip'}, attempt #1 12:58:08 INFO - Downloaded 21340916 bytes. 12:58:08 INFO - Running command: ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip'] in /builds/slave/test/build/tests 12:58:08 INFO - Copy/paste: unzip -q -o /builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip 12:58:08 INFO - Calling ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip'] with output_timeout 1760 12:58:09 INFO - Return code: 0 12:58:09 INFO - Downloading packages: [u'firefox-45.0a1.en-US.linux-x86_64.common.tests.zip', u'firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip'] for test suite category: talos 12:58:09 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:09 INFO - https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip matches https://queue.taskcluster.net 12:58:09 INFO - URL Candidate: http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip 12:58:09 INFO - trying http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip 12:58:09 INFO - Downloading http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip to /builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip 12:58:09 INFO - retry: Calling _download_file with args: (), kwargs: {'url': u'http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip', 'file_name': u'/builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip'}, attempt #1 12:58:10 INFO - Downloaded 21340916 bytes. 12:58:10 INFO - Running command: ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip'] in /builds/slave/test/build/tests 12:58:10 INFO - Copy/paste: unzip -q -o /builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip 12:58:10 INFO - Calling ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.common.tests.zip'] with output_timeout 1760 12:58:11 INFO - Return code: 0 12:58:11 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:11 INFO - https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip matches https://queue.taskcluster.net 12:58:11 INFO - URL Candidate: http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip 12:58:11 INFO - trying http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip 12:58:11 INFO - Downloading http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip to /builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip 12:58:11 INFO - retry: Calling _download_file with args: (), kwargs: {'url': u'http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip', 'file_name': u'/builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip'}, attempt #1 12:58:12 INFO - Downloaded 11130997 bytes. 12:58:12 INFO - Running command: ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip'] in /builds/slave/test/build/tests 12:58:12 INFO - Copy/paste: unzip -q -o /builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip 12:58:12 INFO - Calling ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.talos.tests.zip'] with output_timeout 1760 12:58:12 INFO - Return code: 0 12:58:12 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:12 INFO - https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2 matches https://queue.taskcluster.net 12:58:12 INFO - URL Candidate: http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2 12:58:12 INFO - trying http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2 12:58:12 INFO - Downloading http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2 to /builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2 12:58:12 INFO - retry: Calling _download_file with args: (), kwargs: {'url': 'http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2', 'file_name': '/builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2'}, attempt #1 12:58:14 INFO - Downloaded 55781739 bytes. 12:58:14 INFO - Setting buildbot property build_url to https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2 12:58:14 INFO - mkdir: /builds/slave/test/properties 12:58:14 INFO - Writing buildbot properties ['build_url'] to /builds/slave/test/properties/build_url 12:58:14 INFO - Writing to file /builds/slave/test/properties/build_url 12:58:14 INFO - Contents: 12:58:14 INFO - build_url:https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2 12:58:14 INFO - Running post-action listener: _resource_record_post_action 12:58:14 INFO - Running post-action listener: set_extra_try_arguments 12:58:14 INFO - ##### 12:58:14 INFO - ##### Running populate-webroot step. 12:58:14 INFO - ##### 12:58:14 INFO - Running pre-action listener: _resource_record_pre_action 12:58:14 INFO - Running main action method: populate_webroot 12:58:14 INFO - {'extra_options': {'android': ['--apkPath=%(apk_path)s']}, 12:58:14 INFO - 'mobile-suites': {'remote-tp4m_nochrome': {'tests': ['tp4m']}, 12:58:14 INFO - 'remote-trobocheck2': {'talos_options': ['--fennecIDs', 12:58:14 INFO - '../fennec_ids.txt'], 12:58:14 INFO - 'tests': ['tcheck2']}, 12:58:14 INFO - 'remote-tsvgx': {'talos_options': ['--noChrome', 12:58:14 INFO - '--tppagecycles', 12:58:14 INFO - '7'], 12:58:14 INFO - 'tests': ['tsvgm']}}, 12:58:14 INFO - 'suites': {'chromez': {'tests': ['tresize', 'tcanvasmark']}, 12:58:14 INFO - 'chromez-e10s': {'talos_options': ['--e10s'], 12:58:14 INFO - 'tests': ['tresize', 'tcanvasmark']}, 12:58:14 INFO - 'dromaeojs': {'tests': ['dromaeo_css', 'kraken', 'v8_7']}, 12:58:14 INFO - 'dromaeojs-e10s': {'talos_options': ['--e10s'], 12:58:14 INFO - 'tests': ['dromaeo_css', 'kraken', 'v8_7']}, 12:58:14 INFO - 'g1': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 12:58:14 INFO - 'tests': ['tp5o_scroll', 'glterrain']}, 12:58:14 INFO - 'g1-e10s': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 12:58:14 INFO - 'talos_options': ['--e10s'], 12:58:14 INFO - 'tests': ['tp5o_scroll', 'glterrain']}, 12:58:14 INFO - 'g2': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 12:58:14 INFO - 'tests': ['damp', 'tps']}, 12:58:14 INFO - 'g2-e10s': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 12:58:14 INFO - 'talos_options': ['--e10s'], 12:58:14 INFO - 'tests': ['damp', 'tps']}, 12:58:14 INFO - 'g3': {'tests': ['dromaeo_dom']}, 12:58:14 INFO - 'g3-e10s': {'tests': ['dromaeo_dom']}, 12:58:14 INFO - 'other': {'tests': ['a11yr', 12:58:14 INFO - 'ts_paint', 12:58:14 INFO - 'tpaint', 12:58:14 INFO - 'sessionrestore', 12:58:14 INFO - 'sessionrestore_no_auto_restore']}, 12:58:14 INFO - 'other-e10s': {'talos_options': ['--e10s'], 12:58:14 INFO - 'tests': ['a11yr', 12:58:14 INFO - 'ts_paint', 12:58:14 INFO - 'tpaint', 12:58:14 INFO - 'sessionrestore', 12:58:14 INFO - 'sessionrestore_no_auto_restore']}, 12:58:14 INFO - 'other-e10s_l64': {'talos_options': ['--e10s'], 12:58:14 INFO - 'tests': ['a11yr', 12:58:14 INFO - 'ts_paint', 12:58:14 INFO - 'tpaint', 12:58:14 INFO - 'sessionrestore', 12:58:14 INFO - 'sessionrestore_no_auto_restore']}, 12:58:14 INFO - 'other-e10s_nol64': {'talos_options': ['--e10s'], 12:58:14 INFO - 'tests': ['a11yr', 12:58:14 INFO - 'ts_paint', 12:58:14 INFO - 'tpaint', 12:58:14 INFO - 'sessionrestore', 12:58:14 INFO - 'sessionrestore_no_auto_restore']}, 12:58:14 INFO - 'other_l64': {'tests': ['a11yr', 12:58:14 INFO - 'ts_paint', 12:58:14 INFO - 'tpaint', 12:58:14 INFO - 'sessionrestore', 12:58:14 INFO - 'sessionrestore_no_auto_restore']}, 12:58:14 INFO - 'other_nol64': {'tests': ['a11yr', 12:58:14 INFO - 'ts_paint', 12:58:14 INFO - 'tpaint', 12:58:14 INFO - 'sessionrestore', 12:58:14 INFO - 'sessionrestore_no_auto_restore']}, 12:58:14 INFO - 'svgr': {'tests': ['tsvgx', 12:58:14 INFO - 'tsvgr_opacity', 12:58:14 INFO - 'tart', 12:58:14 INFO - 'tscrollx', 12:58:14 INFO - 'cart']}, 12:58:14 INFO - 'svgr-e10s': {'talos_options': ['--e10s'], 12:58:14 INFO - 'tests': ['tsvgx', 12:58:14 INFO - 'tsvgr_opacity', 12:58:14 INFO - 'tart', 12:58:14 INFO - 'tscrollx', 12:58:14 INFO - 'cart']}, 12:58:14 INFO - 'tp5o': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 12:58:14 INFO - 'tests': ['tp5o']}, 12:58:14 INFO - 'tp5o-e10s': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 12:58:14 INFO - 'talos_options': ['--e10s'], 12:58:14 INFO - 'tests': ['tp5o']}, 12:58:14 INFO - 'xperf': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 12:58:14 INFO - 'talos_options': ['--xperf_path', 12:58:14 INFO - '"c:/Program Files/Microsoft Windows Performance Toolkit/xperf.exe"'], 12:58:14 INFO - 'tests': ['tp5n']}, 12:58:14 INFO - 'xperf-e10s': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 12:58:14 INFO - 'talos_options': ['--e10s', 12:58:14 INFO - '--xperf_path', 12:58:14 INFO - '"c:/Program Files/Microsoft Windows Performance Toolkit/xperf.exe"'], 12:58:14 INFO - 'tests': ['tp5n']}}, 12:58:14 INFO - 'talos.zip': {'path': '', 12:58:14 INFO - 'url': 'http://talos-bundles.pvt.build.mozilla.org/zips/talos.a6052c33d420.zip'}} 12:58:14 INFO - Running post-action listener: _resource_record_post_action 12:58:14 INFO - ##### 12:58:14 INFO - ##### Running create-virtualenv step. 12:58:14 INFO - ##### 12:58:14 INFO - Running pre-action listener: _resource_record_pre_action 12:58:14 INFO - Running main action method: create_virtualenv 12:58:14 INFO - Creating virtualenv /builds/slave/test/build/venv 12:58:14 INFO - Running command: ['/tools/buildbot/bin/python', '/tools/misc-python/virtualenv.py', '--no-site-packages', '--distribute', '/builds/slave/test/build/venv'] in /builds/slave/test/build 12:58:14 INFO - Copy/paste: /tools/buildbot/bin/python /tools/misc-python/virtualenv.py --no-site-packages --distribute /builds/slave/test/build/venv 12:58:14 INFO - The --no-site-packages flag is deprecated; it is now the default behavior. 12:58:14 INFO - Using real prefix '/usr' 12:58:14 INFO - New python executable in /builds/slave/test/build/venv/bin/python 12:58:15 INFO - Installing distribute.............................................................................................................................................................................................done. 12:58:17 INFO - Installing pip.................done. 12:58:17 INFO - Return code: 0 12:58:17 INFO - Installing pip>=1.5 into virtualenv /builds/slave/test/build/venv 12:58:17 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:17 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 12:58:17 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:17 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:17 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 12:58:17 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:17 INFO - retry: Calling run_command with args: [['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'pip>=1.5']], kwargs: {'error_level': 'warning', 'error_list': [{'substr': 'not found or a compiler error:', 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7f84b3729c70>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x25906c0>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x2641900>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x2687b70>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x26d8dc0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x26d9250>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build', 'env': {'LANG': 'en_US.UTF-8', 'TERM': 'linux', 'SHELL': '/bin/bash', 'MOZ_NO_REMOTE': '1', 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 'LANGUAGE': 'en_US:en', 'MAIL': '/var/mail/cltbld', 'SHLVL': '1', 'XPCOM_DEBUG_BREAK': 'warn', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 'TMOUT': '86400', 'PWD': '/builds/slave/test', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 'NO_EM_RESTART': '1', 'HOME': '/home/cltbld', 'DISPLAY': ':0', '_': '/tools/buildbot/bin/python'}}, attempt #1 12:58:17 INFO - Running command: ['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'pip>=1.5'] in /builds/slave/test/build 12:58:17 INFO - Copy/paste: /builds/slave/test/build/venv/bin/pip install --download-cache /builds/slave/test/build/venv/cache --timeout 120 --no-index --find-links http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pvt.build.mozilla.org/pub --find-links http://pypi.pub.build.mozilla.org/pub pip>=1.5 12:58:17 INFO - Using env: {'DISPLAY': ':0', 12:58:17 INFO - 'HOME': '/home/cltbld', 12:58:17 INFO - 'LANG': 'en_US.UTF-8', 12:58:17 INFO - 'LANGUAGE': 'en_US:en', 12:58:17 INFO - 'LOGNAME': 'cltbld', 12:58:17 INFO - 'MAIL': '/var/mail/cltbld', 12:58:17 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 12:58:17 INFO - 'MOZ_NO_REMOTE': '1', 12:58:17 INFO - 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 12:58:17 INFO - 'NO_EM_RESTART': '1', 12:58:17 INFO - 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 12:58:17 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 12:58:17 INFO - 'PWD': '/builds/slave/test', 12:58:17 INFO - 'SHELL': '/bin/bash', 12:58:17 INFO - 'SHLVL': '1', 12:58:17 INFO - 'TERM': 'linux', 12:58:17 INFO - 'TMOUT': '86400', 12:58:17 INFO - 'USER': 'cltbld', 12:58:17 INFO - 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 12:58:17 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 12:58:17 INFO - '_': '/tools/buildbot/bin/python'} 12:58:17 INFO - Ignoring indexes: https://pypi.python.org/simple/ 12:58:17 INFO - Requirement already satisfied (use --upgrade to upgrade): pip>=1.5 in ./venv/lib/python2.7/site-packages/pip-1.5.5-py2.7.egg 12:58:17 INFO - Cleaning up... 12:58:17 INFO - Return code: 0 12:58:17 INFO - Installing psutil>=0.7.1 into virtualenv /builds/slave/test/build/venv 12:58:17 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:17 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 12:58:17 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:17 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:17 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 12:58:17 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:17 INFO - retry: Calling run_command with args: [['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'psutil>=0.7.1']], kwargs: {'error_level': 'warning', 'error_list': [{'substr': 'not found or a compiler error:', 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7f84b3729c70>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x25906c0>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x2641900>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x2687b70>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x26d8dc0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x26d9250>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build', 'env': {'LANG': 'en_US.UTF-8', 'TERM': 'linux', 'SHELL': '/bin/bash', 'MOZ_NO_REMOTE': '1', 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 'LANGUAGE': 'en_US:en', 'MAIL': '/var/mail/cltbld', 'SHLVL': '1', 'XPCOM_DEBUG_BREAK': 'warn', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 'TMOUT': '86400', 'PWD': '/builds/slave/test', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 'NO_EM_RESTART': '1', 'HOME': '/home/cltbld', 'DISPLAY': ':0', '_': '/tools/buildbot/bin/python'}}, attempt #1 12:58:17 INFO - Running command: ['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'psutil>=0.7.1'] in /builds/slave/test/build 12:58:17 INFO - Copy/paste: /builds/slave/test/build/venv/bin/pip install --download-cache /builds/slave/test/build/venv/cache --timeout 120 --no-index --find-links http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pvt.build.mozilla.org/pub --find-links http://pypi.pub.build.mozilla.org/pub psutil>=0.7.1 12:58:17 INFO - Using env: {'DISPLAY': ':0', 12:58:17 INFO - 'HOME': '/home/cltbld', 12:58:17 INFO - 'LANG': 'en_US.UTF-8', 12:58:17 INFO - 'LANGUAGE': 'en_US:en', 12:58:17 INFO - 'LOGNAME': 'cltbld', 12:58:17 INFO - 'MAIL': '/var/mail/cltbld', 12:58:17 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 12:58:17 INFO - 'MOZ_NO_REMOTE': '1', 12:58:17 INFO - 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 12:58:17 INFO - 'NO_EM_RESTART': '1', 12:58:17 INFO - 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 12:58:17 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 12:58:17 INFO - 'PWD': '/builds/slave/test', 12:58:17 INFO - 'SHELL': '/bin/bash', 12:58:17 INFO - 'SHLVL': '1', 12:58:17 INFO - 'TERM': 'linux', 12:58:17 INFO - 'TMOUT': '86400', 12:58:17 INFO - 'USER': 'cltbld', 12:58:17 INFO - 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 12:58:17 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 12:58:17 INFO - '_': '/tools/buildbot/bin/python'} 12:58:17 INFO - Ignoring indexes: https://pypi.python.org/simple/ 12:58:17 INFO - Downloading/unpacking psutil>=0.7.1 12:58:17 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:17 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:17 INFO - http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:17 INFO - http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:17 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:17 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:19 INFO - Creating supposed download cache at /builds/slave/test/build/venv/cache 12:58:19 INFO - Storing download in cache at ./venv/cache/http%3A%2F%2Fpypi.pvt.build.mozilla.org%2Fpub%2Fpsutil-3.1.1.tar.gz 12:58:19 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/psutil/setup.py) egg_info for package psutil 12:58:19 INFO - warning: no previously-included files matching '*' found under directory 'docs/_build' 12:58:19 INFO - warning: manifest_maker: MANIFEST.in, line 18: 'recursive-include' expects ... 12:58:19 INFO - Installing collected packages: psutil 12:58:19 INFO - Running setup.py install for psutil 12:58:19 INFO - building 'psutil._psutil_linux' extension 12:58:19 INFO - gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -DPSUTIL_VERSION=311 -I/usr/include/python2.7 -c psutil/_psutil_linux.c -o build/temp.linux-x86_64-2.7/psutil/_psutil_linux.o 12:58:19 INFO - gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro build/temp.linux-x86_64-2.7/psutil/_psutil_linux.o -o build/lib.linux-x86_64-2.7/psutil/_psutil_linux.so 12:58:19 INFO - building 'psutil._psutil_posix' extension 12:58:19 INFO - gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.7 -c psutil/_psutil_posix.c -o build/temp.linux-x86_64-2.7/psutil/_psutil_posix.o 12:58:20 INFO - gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro build/temp.linux-x86_64-2.7/psutil/_psutil_posix.o -o build/lib.linux-x86_64-2.7/psutil/_psutil_posix.so 12:58:20 INFO - warning: no previously-included files matching '*' found under directory 'docs/_build' 12:58:20 INFO - warning: manifest_maker: MANIFEST.in, line 18: 'recursive-include' expects ... 12:58:20 INFO - Successfully installed psutil 12:58:20 INFO - Cleaning up... 12:58:20 INFO - Return code: 0 12:58:20 INFO - Installing mozsystemmonitor==0.0.0 into virtualenv /builds/slave/test/build/venv 12:58:20 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:20 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 12:58:20 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:20 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:20 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 12:58:20 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:20 INFO - retry: Calling run_command with args: [['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'mozsystemmonitor==0.0.0']], kwargs: {'error_level': 'warning', 'error_list': [{'substr': 'not found or a compiler error:', 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7f84b3729c70>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x25906c0>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x2641900>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x2687b70>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x26d8dc0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x26d9250>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build', 'env': {'LANG': 'en_US.UTF-8', 'TERM': 'linux', 'SHELL': '/bin/bash', 'MOZ_NO_REMOTE': '1', 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 'LANGUAGE': 'en_US:en', 'MAIL': '/var/mail/cltbld', 'SHLVL': '1', 'XPCOM_DEBUG_BREAK': 'warn', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 'TMOUT': '86400', 'PWD': '/builds/slave/test', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 'NO_EM_RESTART': '1', 'HOME': '/home/cltbld', 'DISPLAY': ':0', '_': '/tools/buildbot/bin/python'}}, attempt #1 12:58:20 INFO - Running command: ['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'mozsystemmonitor==0.0.0'] in /builds/slave/test/build 12:58:20 INFO - Copy/paste: /builds/slave/test/build/venv/bin/pip install --download-cache /builds/slave/test/build/venv/cache --timeout 120 --no-index --find-links http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pvt.build.mozilla.org/pub --find-links http://pypi.pub.build.mozilla.org/pub mozsystemmonitor==0.0.0 12:58:20 INFO - Using env: {'DISPLAY': ':0', 12:58:20 INFO - 'HOME': '/home/cltbld', 12:58:20 INFO - 'LANG': 'en_US.UTF-8', 12:58:20 INFO - 'LANGUAGE': 'en_US:en', 12:58:20 INFO - 'LOGNAME': 'cltbld', 12:58:20 INFO - 'MAIL': '/var/mail/cltbld', 12:58:20 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 12:58:20 INFO - 'MOZ_NO_REMOTE': '1', 12:58:20 INFO - 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 12:58:20 INFO - 'NO_EM_RESTART': '1', 12:58:20 INFO - 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 12:58:20 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 12:58:20 INFO - 'PWD': '/builds/slave/test', 12:58:20 INFO - 'SHELL': '/bin/bash', 12:58:20 INFO - 'SHLVL': '1', 12:58:20 INFO - 'TERM': 'linux', 12:58:20 INFO - 'TMOUT': '86400', 12:58:20 INFO - 'USER': 'cltbld', 12:58:20 INFO - 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 12:58:20 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 12:58:20 INFO - '_': '/tools/buildbot/bin/python'} 12:58:20 INFO - Ignoring indexes: https://pypi.python.org/simple/ 12:58:20 INFO - Downloading/unpacking mozsystemmonitor==0.0.0 12:58:20 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:20 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:20 INFO - http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:20 INFO - http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:20 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:20 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:22 INFO - Downloading mozsystemmonitor-0.0.tar.gz 12:58:22 INFO - Storing download in cache at ./venv/cache/http%3A%2F%2Fpypi.pvt.build.mozilla.org%2Fpub%2Fmozsystemmonitor-0.0.tar.gz 12:58:22 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/mozsystemmonitor/setup.py) egg_info for package mozsystemmonitor 12:58:22 INFO - Requirement already satisfied (use --upgrade to upgrade): psutil>=0.7.1 in ./venv/lib/python2.7/site-packages (from mozsystemmonitor==0.0.0) 12:58:22 INFO - Installing collected packages: mozsystemmonitor 12:58:22 INFO - Running setup.py install for mozsystemmonitor 12:58:22 INFO - Successfully installed mozsystemmonitor 12:58:22 INFO - Cleaning up... 12:58:22 INFO - Return code: 0 12:58:22 INFO - Installing blobuploader==1.2.4 into virtualenv /builds/slave/test/build/venv 12:58:22 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:22 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 12:58:22 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:22 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:22 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 12:58:22 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:22 INFO - retry: Calling run_command with args: [['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'blobuploader==1.2.4']], kwargs: {'error_level': 'warning', 'error_list': [{'substr': 'not found or a compiler error:', 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7f84b3729c70>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x25906c0>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x2641900>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x2687b70>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x26d8dc0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x26d9250>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build', 'env': {'LANG': 'en_US.UTF-8', 'TERM': 'linux', 'SHELL': '/bin/bash', 'MOZ_NO_REMOTE': '1', 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 'LANGUAGE': 'en_US:en', 'MAIL': '/var/mail/cltbld', 'SHLVL': '1', 'XPCOM_DEBUG_BREAK': 'warn', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 'TMOUT': '86400', 'PWD': '/builds/slave/test', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 'NO_EM_RESTART': '1', 'HOME': '/home/cltbld', 'DISPLAY': ':0', '_': '/tools/buildbot/bin/python'}}, attempt #1 12:58:22 INFO - Running command: ['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub', 'blobuploader==1.2.4'] in /builds/slave/test/build 12:58:22 INFO - Copy/paste: /builds/slave/test/build/venv/bin/pip install --download-cache /builds/slave/test/build/venv/cache --timeout 120 --no-index --find-links http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pvt.build.mozilla.org/pub --find-links http://pypi.pub.build.mozilla.org/pub blobuploader==1.2.4 12:58:22 INFO - Using env: {'DISPLAY': ':0', 12:58:22 INFO - 'HOME': '/home/cltbld', 12:58:22 INFO - 'LANG': 'en_US.UTF-8', 12:58:22 INFO - 'LANGUAGE': 'en_US:en', 12:58:22 INFO - 'LOGNAME': 'cltbld', 12:58:22 INFO - 'MAIL': '/var/mail/cltbld', 12:58:22 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 12:58:22 INFO - 'MOZ_NO_REMOTE': '1', 12:58:22 INFO - 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 12:58:22 INFO - 'NO_EM_RESTART': '1', 12:58:22 INFO - 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 12:58:22 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 12:58:22 INFO - 'PWD': '/builds/slave/test', 12:58:22 INFO - 'SHELL': '/bin/bash', 12:58:22 INFO - 'SHLVL': '1', 12:58:22 INFO - 'TERM': 'linux', 12:58:22 INFO - 'TMOUT': '86400', 12:58:22 INFO - 'USER': 'cltbld', 12:58:22 INFO - 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 12:58:22 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 12:58:22 INFO - '_': '/tools/buildbot/bin/python'} 12:58:22 INFO - Ignoring indexes: https://pypi.python.org/simple/ 12:58:22 INFO - Downloading/unpacking blobuploader==1.2.4 12:58:22 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:22 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:22 INFO - http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:22 INFO - http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:22 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:22 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:24 INFO - Downloading blobuploader-1.2.4.tar.gz 12:58:24 INFO - Storing download in cache at ./venv/cache/http%3A%2F%2Fpypi.pvt.build.mozilla.org%2Fpub%2Fblobuploader-1.2.4.tar.gz 12:58:24 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/blobuploader/setup.py) egg_info for package blobuploader 12:58:24 INFO - Downloading/unpacking requests==1.2.3. (from blobuploader==1.2.4) 12:58:24 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:24 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:24 INFO - http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:24 INFO - http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:24 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:24 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:24 INFO - Storing download in cache at ./venv/cache/http%3A%2F%2Fpypi.pvt.build.mozilla.org%2Fpub%2Frequests-1.2.3.tar.gz 12:58:24 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/requests/setup.py) egg_info for package requests 12:58:24 INFO - Downloading/unpacking docopt==0.6.1 (from blobuploader==1.2.4) 12:58:24 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:24 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:24 INFO - http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:24 INFO - http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:24 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:24 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:24 INFO - Downloading docopt-0.6.1.tar.gz 12:58:24 INFO - Storing download in cache at ./venv/cache/http%3A%2F%2Fpypi.pvt.build.mozilla.org%2Fpub%2Fdocopt-0.6.1.tar.gz 12:58:24 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/docopt/setup.py) egg_info for package docopt 12:58:24 INFO - Installing collected packages: blobuploader, requests, docopt 12:58:24 INFO - Running setup.py install for blobuploader 12:58:24 INFO - changing mode of build/scripts-2.7/blobberc.py from 664 to 775 12:58:24 INFO - changing mode of /builds/slave/test/build/venv/bin/blobberc.py to 775 12:58:24 INFO - Running setup.py install for requests 12:58:25 INFO - Running setup.py install for docopt 12:58:25 INFO - Successfully installed blobuploader requests docopt 12:58:25 INFO - Cleaning up... 12:58:25 INFO - Return code: 0 12:58:25 INFO - Installing None into virtualenv /builds/slave/test/build/venv 12:58:25 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:25 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 12:58:25 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:25 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:25 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 12:58:25 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:25 INFO - retry: Calling run_command with args: [['/builds/slave/test/build/venv/bin/pip', 'install', '--no-deps', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '-r', '/builds/slave/test/build/tests/config/mozbase_requirements.txt', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub']], kwargs: {'error_level': 'warning', 'error_list': [{'substr': 'not found or a compiler error:', 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7f84b3729c70>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x25906c0>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x2641900>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x2687b70>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x26d8dc0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x26d9250>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build/tests/config', 'env': {'LANG': 'en_US.UTF-8', 'TERM': 'linux', 'SHELL': '/bin/bash', 'MOZ_NO_REMOTE': '1', 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 'LANGUAGE': 'en_US:en', 'MAIL': '/var/mail/cltbld', 'SHLVL': '1', 'XPCOM_DEBUG_BREAK': 'warn', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 'TMOUT': '86400', 'PWD': '/builds/slave/test', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 'NO_EM_RESTART': '1', 'HOME': '/home/cltbld', 'DISPLAY': ':0', '_': '/tools/buildbot/bin/python'}}, attempt #1 12:58:25 INFO - Running command: ['/builds/slave/test/build/venv/bin/pip', 'install', '--no-deps', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '-r', '/builds/slave/test/build/tests/config/mozbase_requirements.txt', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub'] in /builds/slave/test/build/tests/config 12:58:25 INFO - Copy/paste: /builds/slave/test/build/venv/bin/pip install --no-deps --download-cache /builds/slave/test/build/venv/cache --timeout 120 -r /builds/slave/test/build/tests/config/mozbase_requirements.txt --no-index --find-links http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pvt.build.mozilla.org/pub --find-links http://pypi.pub.build.mozilla.org/pub 12:58:25 INFO - Using env: {'DISPLAY': ':0', 12:58:25 INFO - 'HOME': '/home/cltbld', 12:58:25 INFO - 'LANG': 'en_US.UTF-8', 12:58:25 INFO - 'LANGUAGE': 'en_US:en', 12:58:25 INFO - 'LOGNAME': 'cltbld', 12:58:25 INFO - 'MAIL': '/var/mail/cltbld', 12:58:25 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 12:58:25 INFO - 'MOZ_NO_REMOTE': '1', 12:58:25 INFO - 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 12:58:25 INFO - 'NO_EM_RESTART': '1', 12:58:25 INFO - 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 12:58:25 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 12:58:25 INFO - 'PWD': '/builds/slave/test', 12:58:25 INFO - 'SHELL': '/bin/bash', 12:58:25 INFO - 'SHLVL': '1', 12:58:25 INFO - 'TERM': 'linux', 12:58:25 INFO - 'TMOUT': '86400', 12:58:25 INFO - 'USER': 'cltbld', 12:58:25 INFO - 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 12:58:25 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 12:58:25 INFO - '_': '/tools/buildbot/bin/python'} 12:58:25 INFO - Ignoring indexes: https://pypi.python.org/simple/ 12:58:25 INFO - Unpacking /builds/slave/test/build/tests/mozbase/manifestparser 12:58:25 INFO - Running setup.py (path:/tmp/pip-r0mHMm-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/manifestparser 12:58:25 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozcrash 12:58:25 INFO - Running setup.py (path:/tmp/pip-3v9Wgz-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozcrash 12:58:25 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozdebug 12:58:25 INFO - Running setup.py (path:/tmp/pip-jYTpGI-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozdebug 12:58:25 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozdevice 12:58:25 INFO - Running setup.py (path:/tmp/pip-uyTEkr-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozdevice 12:58:25 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozfile 12:58:25 INFO - Running setup.py (path:/tmp/pip-gglXI4-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozfile 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozhttpd 12:58:26 INFO - Running setup.py (path:/tmp/pip-QqaTL4-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozhttpd 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozinfo 12:58:26 INFO - Running setup.py (path:/tmp/pip-nG9j09-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozinfo 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozinstall 12:58:26 INFO - Running setup.py (path:/tmp/pip-VR6hyr-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozinstall 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozleak 12:58:26 INFO - Running setup.py (path:/tmp/pip-LROeCc-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozleak 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozlog 12:58:26 INFO - Running setup.py (path:/tmp/pip-lL2WAj-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozlog 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/moznetwork 12:58:26 INFO - Running setup.py (path:/tmp/pip-veK8Y2-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/moznetwork 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozprocess 12:58:26 INFO - Running setup.py (path:/tmp/pip-CpZXaT-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozprocess 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozprofile 12:58:26 INFO - Running setup.py (path:/tmp/pip-hPuqnd-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozprofile 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozrunner 12:58:26 INFO - Running setup.py (path:/tmp/pip-C4KwNJ-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozrunner 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozscreenshot 12:58:26 INFO - Running setup.py (path:/tmp/pip-S2YJ6l-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozscreenshot 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/moztest 12:58:26 INFO - Running setup.py (path:/tmp/pip-BpsFH9-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/moztest 12:58:26 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozversion 12:58:26 INFO - Running setup.py (path:/tmp/pip-RMs4Nm-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozversion 12:58:26 INFO - Installing collected packages: manifestparser, mozcrash, mozdebug, mozdevice, mozfile, mozhttpd, mozinfo, mozInstall, mozleak, mozlog, moznetwork, mozprocess, mozprofile, mozrunner, mozscreenshot, moztest, mozversion 12:58:26 INFO - Running setup.py install for manifestparser 12:58:26 INFO - Installing manifestparser script to /builds/slave/test/build/venv/bin 12:58:26 INFO - Running setup.py install for mozcrash 12:58:27 INFO - Running setup.py install for mozdebug 12:58:27 INFO - Running setup.py install for mozdevice 12:58:27 INFO - Installing sutini script to /builds/slave/test/build/venv/bin 12:58:27 INFO - Installing dm script to /builds/slave/test/build/venv/bin 12:58:27 INFO - Running setup.py install for mozfile 12:58:27 INFO - Running setup.py install for mozhttpd 12:58:27 INFO - Installing mozhttpd script to /builds/slave/test/build/venv/bin 12:58:27 INFO - Running setup.py install for mozinfo 12:58:27 INFO - Installing mozinfo script to /builds/slave/test/build/venv/bin 12:58:27 INFO - Running setup.py install for mozInstall 12:58:27 INFO - Installing moz_remove_from_system script to /builds/slave/test/build/venv/bin 12:58:27 INFO - Installing mozuninstall script to /builds/slave/test/build/venv/bin 12:58:27 INFO - Installing mozinstall script to /builds/slave/test/build/venv/bin 12:58:27 INFO - Installing moz_add_to_system script to /builds/slave/test/build/venv/bin 12:58:27 INFO - Running setup.py install for mozleak 12:58:27 INFO - Running setup.py install for mozlog 12:58:27 INFO - Installing structlog script to /builds/slave/test/build/venv/bin 12:58:27 INFO - Running setup.py install for moznetwork 12:58:27 INFO - Installing moznetwork script to /builds/slave/test/build/venv/bin 12:58:27 INFO - Running setup.py install for mozprocess 12:58:28 INFO - Running setup.py install for mozprofile 12:58:28 INFO - Installing mozprofile script to /builds/slave/test/build/venv/bin 12:58:28 INFO - Installing diff-profiles script to /builds/slave/test/build/venv/bin 12:58:28 INFO - Installing view-profile script to /builds/slave/test/build/venv/bin 12:58:28 INFO - Running setup.py install for mozrunner 12:58:28 INFO - Installing mozrunner script to /builds/slave/test/build/venv/bin 12:58:28 INFO - Running setup.py install for mozscreenshot 12:58:28 INFO - Running setup.py install for moztest 12:58:28 INFO - Running setup.py install for mozversion 12:58:28 INFO - Installing mozversion script to /builds/slave/test/build/venv/bin 12:58:28 INFO - Successfully installed manifestparser mozcrash mozdebug mozdevice mozfile mozhttpd mozinfo mozInstall mozleak mozlog moznetwork mozprocess mozprofile mozrunner mozscreenshot moztest mozversion 12:58:28 INFO - Cleaning up... 12:58:28 INFO - Return code: 0 12:58:28 INFO - Installing None into virtualenv /builds/slave/test/build/venv 12:58:28 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:28 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 12:58:28 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:28 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:28 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 12:58:28 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:28 INFO - retry: Calling run_command with args: [['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '-r', '/builds/slave/test/build/tests/config/mozbase_requirements.txt', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub']], kwargs: {'error_level': 'warning', 'error_list': [{'substr': 'not found or a compiler error:', 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7f84b3729c70>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x25906c0>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x2641900>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x2687b70>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x26d8dc0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x26d9250>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build/tests/config', 'env': {'LANG': 'en_US.UTF-8', 'TERM': 'linux', 'SHELL': '/bin/bash', 'MOZ_NO_REMOTE': '1', 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 'LANGUAGE': 'en_US:en', 'MAIL': '/var/mail/cltbld', 'SHLVL': '1', 'XPCOM_DEBUG_BREAK': 'warn', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 'TMOUT': '86400', 'PWD': '/builds/slave/test', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 'NO_EM_RESTART': '1', 'HOME': '/home/cltbld', 'DISPLAY': ':0', '_': '/tools/buildbot/bin/python'}}, attempt #1 12:58:28 INFO - Running command: ['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '-r', '/builds/slave/test/build/tests/config/mozbase_requirements.txt', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub'] in /builds/slave/test/build/tests/config 12:58:28 INFO - Copy/paste: /builds/slave/test/build/venv/bin/pip install --download-cache /builds/slave/test/build/venv/cache --timeout 120 -r /builds/slave/test/build/tests/config/mozbase_requirements.txt --no-index --find-links http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pvt.build.mozilla.org/pub --find-links http://pypi.pub.build.mozilla.org/pub 12:58:28 INFO - Using env: {'DISPLAY': ':0', 12:58:28 INFO - 'HOME': '/home/cltbld', 12:58:28 INFO - 'LANG': 'en_US.UTF-8', 12:58:28 INFO - 'LANGUAGE': 'en_US:en', 12:58:28 INFO - 'LOGNAME': 'cltbld', 12:58:28 INFO - 'MAIL': '/var/mail/cltbld', 12:58:28 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 12:58:28 INFO - 'MOZ_NO_REMOTE': '1', 12:58:28 INFO - 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 12:58:28 INFO - 'NO_EM_RESTART': '1', 12:58:28 INFO - 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 12:58:28 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 12:58:28 INFO - 'PWD': '/builds/slave/test', 12:58:28 INFO - 'SHELL': '/bin/bash', 12:58:28 INFO - 'SHLVL': '1', 12:58:28 INFO - 'TERM': 'linux', 12:58:28 INFO - 'TMOUT': '86400', 12:58:28 INFO - 'USER': 'cltbld', 12:58:28 INFO - 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 12:58:28 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 12:58:28 INFO - '_': '/tools/buildbot/bin/python'} 12:58:28 INFO - Ignoring indexes: https://pypi.python.org/simple/ 12:58:28 INFO - Unpacking /builds/slave/test/build/tests/mozbase/manifestparser 12:58:28 INFO - Running setup.py (path:/tmp/pip-G0_DfQ-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/manifestparser 12:58:28 INFO - Requirement already satisfied (use --upgrade to upgrade): manifestparser==1.1 from file:///builds/slave/test/build/tests/mozbase/manifestparser in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 1)) 12:58:28 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozcrash 12:58:28 INFO - Running setup.py (path:/tmp/pip-U8UAiq-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozcrash 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozcrash==0.16 from file:///builds/slave/test/build/tests/mozbase/mozcrash in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 2)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozdebug 12:58:29 INFO - Running setup.py (path:/tmp/pip-gUot64-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozdebug 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozdebug==0.1 from file:///builds/slave/test/build/tests/mozbase/mozdebug in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 3)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozdevice 12:58:29 INFO - Running setup.py (path:/tmp/pip-64Pj4h-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozdevice 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozdevice==0.47 from file:///builds/slave/test/build/tests/mozbase/mozdevice in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 4)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozfile 12:58:29 INFO - Running setup.py (path:/tmp/pip-WiCpfs-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozfile 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozfile==1.2 from file:///builds/slave/test/build/tests/mozbase/mozfile in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 5)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozhttpd 12:58:29 INFO - Running setup.py (path:/tmp/pip-EsAPzE-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozhttpd 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozhttpd==0.7 from file:///builds/slave/test/build/tests/mozbase/mozhttpd in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 6)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozinfo 12:58:29 INFO - Running setup.py (path:/tmp/pip-FSMQWp-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozinfo 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozinfo==0.9 from file:///builds/slave/test/build/tests/mozbase/mozinfo in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 7)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozinstall 12:58:29 INFO - Running setup.py (path:/tmp/pip-I8RS8t-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozinstall 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozInstall==1.12 from file:///builds/slave/test/build/tests/mozbase/mozinstall in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 8)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozleak 12:58:29 INFO - Running setup.py (path:/tmp/pip-mV4yn7-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozleak 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozleak==0.1 from file:///builds/slave/test/build/tests/mozbase/mozleak in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 9)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozlog 12:58:29 INFO - Running setup.py (path:/tmp/pip-3sACmD-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozlog 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozlog==3.0 from file:///builds/slave/test/build/tests/mozbase/mozlog in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 10)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/moznetwork 12:58:29 INFO - Running setup.py (path:/tmp/pip-h3QFH3-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/moznetwork 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): moznetwork==0.27 from file:///builds/slave/test/build/tests/mozbase/moznetwork in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 11)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozprocess 12:58:29 INFO - Running setup.py (path:/tmp/pip-QHkTrF-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozprocess 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozprocess==0.22 from file:///builds/slave/test/build/tests/mozbase/mozprocess in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 12)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozprofile 12:58:29 INFO - Running setup.py (path:/tmp/pip-5elCq3-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozprofile 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozprofile==0.27 from file:///builds/slave/test/build/tests/mozbase/mozprofile in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 13)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozrunner 12:58:29 INFO - Running setup.py (path:/tmp/pip-vduA6f-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozrunner 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozrunner==6.11 from file:///builds/slave/test/build/tests/mozbase/mozrunner in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 14)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozscreenshot 12:58:29 INFO - Running setup.py (path:/tmp/pip-S1a7OV-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozscreenshot 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): mozscreenshot==0.1 from file:///builds/slave/test/build/tests/mozbase/mozscreenshot in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 15)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/moztest 12:58:29 INFO - Running setup.py (path:/tmp/pip-tAudoN-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/moztest 12:58:29 INFO - Requirement already satisfied (use --upgrade to upgrade): moztest==0.7 from file:///builds/slave/test/build/tests/mozbase/moztest in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 16)) 12:58:29 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozversion 12:58:29 INFO - Running setup.py (path:/tmp/pip-l68UME-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozversion 12:58:30 INFO - Requirement already satisfied (use --upgrade to upgrade): mozversion==1.4 from file:///builds/slave/test/build/tests/mozbase/mozversion in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 17)) 12:58:30 INFO - Requirement already satisfied (use --upgrade to upgrade): mozfile>=1.0 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from mozcrash==0.16->-r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 2)) 12:58:30 INFO - Requirement already satisfied (use --upgrade to upgrade): mozlog>=3.0 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from mozcrash==0.16->-r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 2)) 12:58:30 INFO - Requirement already satisfied (use --upgrade to upgrade): mozinfo in /builds/slave/test/build/venv/lib/python2.7/site-packages (from mozdebug==0.1->-r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 3)) 12:58:30 INFO - Requirement already satisfied (use --upgrade to upgrade): moznetwork>=0.24 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from mozdevice==0.47->-r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 4)) 12:58:30 INFO - Requirement already satisfied (use --upgrade to upgrade): mozprocess>=0.19 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from mozdevice==0.47->-r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 4)) 12:58:30 INFO - Downloading/unpacking blessings>=1.3 (from mozlog==3.0->-r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 10)) 12:58:30 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:30 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:30 INFO - http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:30 INFO - http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com has it available 12:58:30 INFO - http://pypi.pvt.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pvt.build.mozilla.org has it available 12:58:30 INFO - http://pypi.pub.build.mozilla.org/pub uses an insecure transport scheme (http). Consider using https if pypi.pub.build.mozilla.org has it available 12:58:31 INFO - Downloading blessings-1.5.1.tar.gz 12:58:31 INFO - Storing download in cache at /builds/slave/test/build/venv/cache/http%3A%2F%2Fpypi.pvt.build.mozilla.org%2Fpub%2Fblessings-1.5.1.tar.gz 12:58:31 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/blessings/setup.py) egg_info for package blessings 12:58:31 INFO - Installing collected packages: blessings 12:58:31 INFO - Running setup.py install for blessings 12:58:31 INFO - Successfully installed blessings 12:58:31 INFO - Cleaning up... 12:58:31 INFO - Return code: 0 12:58:31 INFO - Done creating virtualenv /builds/slave/test/build/venv. 12:58:31 INFO - Getting output from command: ['/builds/slave/test/build/venv/bin/pip', 'freeze'] 12:58:31 INFO - Copy/paste: /builds/slave/test/build/venv/bin/pip freeze 12:58:32 INFO - Reading from file tmpfile_stdout 12:58:32 INFO - Current package versions: 12:58:32 INFO - argparse == 1.2.1 12:58:32 INFO - blessings == 1.5.1 12:58:32 INFO - blobuploader == 1.2.4 12:58:32 INFO - docopt == 0.6.1 12:58:32 INFO - manifestparser == 1.1 12:58:32 INFO - mozInstall == 1.12 12:58:32 INFO - mozcrash == 0.16 12:58:32 INFO - mozdebug == 0.1 12:58:32 INFO - mozdevice == 0.47 12:58:32 INFO - mozfile == 1.2 12:58:32 INFO - mozhttpd == 0.7 12:58:32 INFO - mozinfo == 0.9 12:58:32 INFO - mozleak == 0.1 12:58:32 INFO - mozlog == 3.0 12:58:32 INFO - moznetwork == 0.27 12:58:32 INFO - mozprocess == 0.22 12:58:32 INFO - mozprofile == 0.27 12:58:32 INFO - mozrunner == 6.11 12:58:32 INFO - mozscreenshot == 0.1 12:58:32 INFO - mozsystemmonitor == 0.0 12:58:32 INFO - moztest == 0.7 12:58:32 INFO - mozversion == 1.4 12:58:32 INFO - psutil == 3.1.1 12:58:32 INFO - requests == 1.2.3 12:58:32 INFO - wsgiref == 0.1.2 12:58:32 INFO - Installing None into virtualenv /builds/slave/test/build/venv 12:58:32 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:32 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 12:58:32 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:32 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:32 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 12:58:32 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 12:58:32 INFO - retry: Calling run_command with args: [['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '-r', '/builds/slave/test/build/tests/talos/requirements.txt', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub']], kwargs: {'error_level': 'warning', 'error_list': [{'substr': 'not found or a compiler error:', 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7f84b3729c70>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x25906c0>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x2641900>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x2687b70>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x26d8dc0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x26d9250>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build/tests/talos', 'env': {'LANG': 'en_US.UTF-8', 'TERM': 'linux', 'SHELL': '/bin/bash', 'MOZ_NO_REMOTE': '1', 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 'LANGUAGE': 'en_US:en', 'MAIL': '/var/mail/cltbld', 'SHLVL': '1', 'XPCOM_DEBUG_BREAK': 'warn', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 'TMOUT': '86400', 'PWD': '/builds/slave/test', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 'NO_EM_RESTART': '1', 'HOME': '/home/cltbld', 'DISPLAY': ':0', '_': '/tools/buildbot/bin/python'}}, attempt #1 12:58:32 INFO - Running command: ['/builds/slave/test/build/venv/bin/pip', 'install', '--download-cache', '/builds/slave/test/build/venv/cache', '--timeout', '120', '-r', '/builds/slave/test/build/tests/talos/requirements.txt', '--no-index', '--find-links', 'http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub', '--find-links', 'http://pypi.pvt.build.mozilla.org/pub', '--find-links', 'http://pypi.pub.build.mozilla.org/pub'] in /builds/slave/test/build/tests/talos 12:58:32 INFO - Copy/paste: /builds/slave/test/build/venv/bin/pip install --download-cache /builds/slave/test/build/venv/cache --timeout 120 -r /builds/slave/test/build/tests/talos/requirements.txt --no-index --find-links http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub --find-links http://pypi.pvt.build.mozilla.org/pub --find-links http://pypi.pub.build.mozilla.org/pub 12:58:32 INFO - Using env: {'DISPLAY': ':0', 12:58:32 INFO - 'HOME': '/home/cltbld', 12:58:32 INFO - 'LANG': 'en_US.UTF-8', 12:58:32 INFO - 'LANGUAGE': 'en_US:en', 12:58:32 INFO - 'LOGNAME': 'cltbld', 12:58:32 INFO - 'MAIL': '/var/mail/cltbld', 12:58:32 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 12:58:32 INFO - 'MOZ_NO_REMOTE': '1', 12:58:32 INFO - 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 12:58:32 INFO - 'NO_EM_RESTART': '1', 12:58:32 INFO - 'PATH': '/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 12:58:32 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 12:58:32 INFO - 'PWD': '/builds/slave/test', 12:58:32 INFO - 'SHELL': '/bin/bash', 12:58:32 INFO - 'SHLVL': '1', 12:58:32 INFO - 'TERM': 'linux', 12:58:32 INFO - 'TMOUT': '86400', 12:58:32 INFO - 'USER': 'cltbld', 12:58:32 INFO - 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 12:58:32 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 12:58:32 INFO - '_': '/tools/buildbot/bin/python'} 12:58:32 INFO - Ignoring indexes: https://pypi.python.org/simple/ 12:58:32 INFO - Requirement already satisfied (use --upgrade to upgrade): mozcrash>=0.15 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/talos/requirements.txt (line 1)) 12:58:32 INFO - Requirement already satisfied (use --upgrade to upgrade): mozfile>=1.2 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/talos/requirements.txt (line 2)) 12:58:32 INFO - Requirement already satisfied (use --upgrade to upgrade): mozhttpd>=0.7 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/talos/requirements.txt (line 3)) 12:58:32 INFO - Requirement already satisfied (use --upgrade to upgrade): mozinfo>=0.8 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/talos/requirements.txt (line 4)) 12:58:32 INFO - Requirement already satisfied (use --upgrade to upgrade): mozprocess>=0.22 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/talos/requirements.txt (line 5)) 12:58:32 INFO - Requirement already satisfied (use --upgrade to upgrade): mozversion>=1.3 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/talos/requirements.txt (line 6)) 12:58:32 INFO - Requirement already satisfied (use --upgrade to upgrade): mozprofile>=0.25 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/talos/requirements.txt (line 7)) 12:58:32 INFO - Requirement already satisfied (use --upgrade to upgrade): psutil>=3.1.1 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from -r /builds/slave/test/build/tests/talos/requirements.txt (line 8)) 12:58:32 INFO - Requirement already satisfied (use --upgrade to upgrade): mozlog>=3.0 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from mozcrash>=0.15->-r /builds/slave/test/build/tests/talos/requirements.txt (line 1)) 12:58:32 INFO - Requirement already satisfied (use --upgrade to upgrade): moznetwork>=0.24 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from mozhttpd>=0.7->-r /builds/slave/test/build/tests/talos/requirements.txt (line 3)) 12:58:32 INFO - Requirement already satisfied (use --upgrade to upgrade): blessings>=1.3 in /builds/slave/test/build/venv/lib/python2.7/site-packages (from mozlog>=3.0->mozcrash>=0.15->-r /builds/slave/test/build/tests/talos/requirements.txt (line 1)) 12:58:32 INFO - Cleaning up... 12:58:32 INFO - Return code: 0 12:58:32 INFO - Running post-action listener: _resource_record_post_action 12:58:32 INFO - Running post-action listener: _start_resource_monitoring 12:58:32 INFO - Starting resource monitoring. 12:58:32 INFO - ##### 12:58:32 INFO - ##### Running install step. 12:58:32 INFO - ##### 12:58:32 INFO - Running pre-action listener: _resource_record_pre_action 12:58:32 INFO - Running main action method: install 12:58:32 INFO - Getting output from command: ['/builds/slave/test/build/venv/bin/pip', 'freeze'] 12:58:32 INFO - Copy/paste: /builds/slave/test/build/venv/bin/pip freeze 12:58:32 INFO - Reading from file tmpfile_stdout 12:58:32 INFO - Detecting whether we're running mozinstall >=1.0... 12:58:32 INFO - Getting output from command: ['/builds/slave/test/build/venv/bin/mozinstall', '-h'] 12:58:32 INFO - Copy/paste: /builds/slave/test/build/venv/bin/mozinstall -h 12:58:32 INFO - Reading from file tmpfile_stdout 12:58:32 INFO - Output received: 12:58:32 INFO - Usage: mozinstall [options] installer 12:58:32 INFO - Options: 12:58:32 INFO - -h, --help show this help message and exit 12:58:32 INFO - -d DEST, --destination=DEST 12:58:32 INFO - Directory to install application into. [default: 12:58:32 INFO - "/builds/slave/test"] 12:58:32 INFO - --app=APP Application being installed. [default: firefox] 12:58:32 INFO - mkdir: /builds/slave/test/build/application 12:58:32 INFO - Getting output from command: ['/builds/slave/test/build/venv/bin/mozinstall', '/builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2', '--destination', '/builds/slave/test/build/application'] 12:58:32 INFO - Copy/paste: /builds/slave/test/build/venv/bin/mozinstall /builds/slave/test/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2 --destination /builds/slave/test/build/application 12:58:46 INFO - Reading from file tmpfile_stdout 12:58:46 INFO - Output received: 12:58:46 INFO - /builds/slave/test/build/application/firefox/firefox 12:58:46 INFO - Running post-action listener: _resource_record_post_action 12:58:46 INFO - ##### 12:58:46 INFO - ##### Running run-tests step. 12:58:46 INFO - ##### 12:58:46 INFO - Running pre-action listener: _resource_record_pre_action 12:58:46 INFO - Running main action method: run_tests 12:58:46 INFO - Running command: ['/builds/slave/test/build/venv/bin/python', '--version'] 12:58:46 INFO - Copy/paste: /builds/slave/test/build/venv/bin/python --version 12:58:46 INFO - Python 2.7.3 12:58:46 INFO - Return code: 0 12:58:46 INFO - grabbing minidump binary from tooltool 12:58:46 INFO - proxxy config: {'regions': ['.use1.', '.usw2.', '.scl3'], 'instances': ['proxxy1.srv.releng.use1.mozilla.com', 'proxxy1.srv.releng.usw2.mozilla.com', 'proxxy1.srv.releng.scl3.mozilla.com'], 'urls': [('http://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp.mozilla.org', 'ftp.mozilla.org'), ('https://ftp-ssl.mozilla.org', 'ftp.mozilla.org'), ('http://pvtbuilds.pvt.build.mozilla.org', 'pvtbuilds.mozilla.org'), ('http://pypi.pvt.build.mozilla.org', 'pypi.pvt.build.mozilla.org'), ('http://pypi.pub.build.mozilla.org', 'pypi.pub.build.mozilla.org'), ('https://queue.taskcluster.net', 'queue.taskcluster.net')]} 12:58:46 INFO - retry: Calling run_command with args: (['/tools/tooltool.py', '--url', 'https://api.pub.build.mozilla.org/tooltool/', '--authentication-file', '/builds/relengapi.tok', 'fetch', '-m', '/builds/slave/test/build/tests/config/tooltool-manifests/linux64/releng.manifest', '-o', '-c', '/builds/tooltool_cache'],), kwargs: {'error_list': [{'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x2687b70>, 'level': 'warning'}, {'substr': 'Traceback (most recent call last)', 'level': 'error'}, {'substr': 'SyntaxError: ', 'level': 'error'}, {'substr': 'TypeError: ', 'level': 'error'}, {'substr': 'NameError: ', 'level': 'error'}, {'substr': 'ZeroDivisionError: ', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x26d8dc0>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x26d9250>, 'level': 'critical'}, {'substr': 'ERROR - ', 'level': 'error'}], 'cwd': '/builds/slave/test/build', 'privileged': False}, attempt #1 12:58:46 INFO - Running command: ['/tools/tooltool.py', '--url', 'https://api.pub.build.mozilla.org/tooltool/', '--authentication-file', '/builds/relengapi.tok', 'fetch', '-m', '/builds/slave/test/build/tests/config/tooltool-manifests/linux64/releng.manifest', '-o', '-c', '/builds/tooltool_cache'] in /builds/slave/test/build 12:58:46 INFO - Copy/paste: /tools/tooltool.py --url https://api.pub.build.mozilla.org/tooltool/ --authentication-file /builds/relengapi.tok fetch -m /builds/slave/test/build/tests/config/tooltool-manifests/linux64/releng.manifest -o -c /builds/tooltool_cache 12:58:46 INFO - INFO - File linux64-minidump_stackwalk retrieved from local cache /builds/tooltool_cache 12:58:46 INFO - Return code: 0 12:58:46 INFO - Chmoding /builds/slave/test/build/linux64-minidump_stackwalk to 0755 12:58:46 INFO - mkdir: /builds/slave/test/build/blobber_upload_dir 12:58:46 INFO - ENV: MOZ_UPLOAD_DIR is now /builds/slave/test/build/blobber_upload_dir 12:58:46 INFO - ENV: MINIDUMP_STACKWALK is now /builds/slave/test/build/linux64-minidump_stackwalk 12:58:46 INFO - ENV: MINIDUMP_SAVE_PATH is now /builds/slave/test/build/blobber_upload_dir 12:58:46 INFO - Running command: ['/builds/slave/test/build/venv/bin/python', '/builds/slave/test/build/tests/talos/talos/run_tests.py', '--debug', '--branchName', 'Fx-Team-Non-PGO', '--suite', 'other-e10s', '--executablePath', '/builds/slave/test/build/application/firefox/firefox', '--symbolsPath', 'https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.crashreporter-symbols.zip', '--title', 'talos-linux64-ix-053', '--webServer', 'localhost'] in /builds/slave/test/build 12:58:46 INFO - Copy/paste: /builds/slave/test/build/venv/bin/python /builds/slave/test/build/tests/talos/talos/run_tests.py --debug --branchName Fx-Team-Non-PGO --suite other-e10s --executablePath /builds/slave/test/build/application/firefox/firefox --symbolsPath https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.crashreporter-symbols.zip --title talos-linux64-ix-053 --webServer localhost 12:58:46 INFO - Using env: {'DISPLAY': ':0', 12:58:46 INFO - 'HOME': '/home/cltbld', 12:58:46 INFO - 'LANG': 'en_US.UTF-8', 12:58:46 INFO - 'LANGUAGE': 'en_US:en', 12:58:46 INFO - 'LOGNAME': 'cltbld', 12:58:46 INFO - 'MAIL': '/var/mail/cltbld', 12:58:46 INFO - 'MINIDUMP_SAVE_PATH': '/builds/slave/test/build/blobber_upload_dir', 12:58:46 INFO - 'MINIDUMP_STACKWALK': '/builds/slave/test/build/linux64-minidump_stackwalk', 12:58:46 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 12:58:46 INFO - 'MOZ_NO_REMOTE': '1', 12:58:46 INFO - 'MOZ_UPLOAD_DIR': '/builds/slave/test/build/blobber_upload_dir', 12:58:46 INFO - 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript', 12:58:46 INFO - 'NO_EM_RESTART': '1', 12:58:46 INFO - 'PATH': '/builds/slave/test/build/venv/bin:/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games', 12:58:46 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 12:58:46 INFO - 'PWD': '/builds/slave/test', 12:58:46 INFO - 'PYTHONPATH': '/builds/slave/test/build/tests/talos', 12:58:46 INFO - 'SHELL': '/bin/bash', 12:58:46 INFO - 'SHLVL': '1', 12:58:46 INFO - 'TERM': 'linux', 12:58:46 INFO - 'TMOUT': '86400', 12:58:46 INFO - 'USER': 'cltbld', 12:58:46 INFO - 'XDG_SESSION_COOKIE': '919420d7ee4ef147bef0346300000385-1448312283.868710-972446830', 12:58:46 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 12:58:46 INFO - '_': '/tools/buildbot/bin/python'} 12:58:46 INFO - Calling ['/builds/slave/test/build/venv/bin/python', '/builds/slave/test/build/tests/talos/talos/run_tests.py', '--debug', '--branchName', 'Fx-Team-Non-PGO', '--suite', 'other-e10s', '--executablePath', '/builds/slave/test/build/application/firefox/firefox', '--symbolsPath', 'https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.crashreporter-symbols.zip', '--title', 'talos-linux64-ix-053', '--webServer', 'localhost'] with output_timeout 3600 12:58:47 INFO - mozversion INFO | application_buildid: 20151120090830 12:58:47 INFO - mozversion INFO | application_changeset: a0db720c980e3fbacf92c03566e8ffea5fdefd2d 12:58:47 INFO - mozversion INFO | application_display_name: Nightly 12:58:47 INFO - mozversion INFO | application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384} 12:58:47 INFO - mozversion INFO | application_name: Firefox 12:58:47 INFO - mozversion INFO | application_remotingname: firefox 12:58:47 INFO - mozversion INFO | application_repository: https://hg.mozilla.org/integration/fx-team 12:58:47 INFO - mozversion INFO | application_vendor: Mozilla 12:58:47 INFO - mozversion INFO | application_version: 45.0a1 12:58:47 INFO - mozversion INFO | platform_buildid: 20151120090830 12:58:47 INFO - mozversion INFO | platform_changeset: a0db720c980e3fbacf92c03566e8ffea5fdefd2d 12:58:47 INFO - mozversion INFO | platform_repository: https://hg.mozilla.org/integration/fx-team 12:58:47 INFO - mozversion INFO | platform_version: 45.0a1 12:58:47 INFO - 2015-11-23 12:58:47,071 DEBUG : using testdate: 1448312327 12:58:47 INFO - 2015-11-23 12:58:47,071 DEBUG : actual date: 1448312327 12:58:47 INFO - 2015-11-23 12:58:47,079 INFO : starting webserver on 'localhost:53751' 12:58:47 INFO - 2015-11-23 12:58:47,080 INFO : Starting test suite talos-linux64-ix-053.e 12:58:47 INFO - 2015-11-23 12:58:47,080 INFO : Starting test a11yr 12:58:47 INFO - 2015-11-23 12:58:47,080 DEBUG : operating with platform_type : linux_ 12:58:47 INFO - 2015-11-23 12:58:47,081 INFO : Initialising browser for a11yr test... 12:58:47 INFO - 2015-11-23 12:58:47,095 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpIv2Rcr/profile http://localhost:53751/getInfo.html 12:58:51 INFO - 2015-11-23 12:58:51,416 DEBUG : BROWSER_OUTPUT: __metrics Screen width/height:1600/1200 12:58:51 INFO - 2015-11-23 12:58:51,416 DEBUG : BROWSER_OUTPUT: colorDepth:24 12:58:51 INFO - 2015-11-23 12:58:51,416 DEBUG : BROWSER_OUTPUT: Browser inner width/height: 1024/697 12:58:51 INFO - 2015-11-23 12:58:51,416 DEBUG : BROWSER_OUTPUT: __metrics 12:58:52 INFO - 2015-11-23 12:58:52,493 INFO : Browser initialized. 12:58:52 INFO - 2015-11-23 12:58:52,494 INFO : Running cycle 1/1 for a11yr test... 12:58:52 INFO - 2015-11-23 12:58:52,494 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpIv2Rcr/profile -tp file:/builds/slave/test/build/tests/talos/talos/tests/a11y/a11y.manifest.develop -tpchrome -tpmozafterpaint -tpnoisy -tpcycles 1 -tppagecycles 25 12:59:04 INFO - 2015-11-23 12:59:04,427 DEBUG : BROWSER_OUTPUT: RSS: Main: 141611008 12:59:04 INFO - 2015-11-23 12:59:04,427 DEBUG : BROWSER_OUTPUT: 12:59:05 INFO - 2015-11-23 12:59:05,696 DEBUG : BROWSER_OUTPUT: Cycle 1(1): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:05 INFO - 2015-11-23 12:59:05,837 DEBUG : BROWSER_OUTPUT: 12:59:05 INFO - 2015-11-23 12:59:05,837 DEBUG : BROWSER_OUTPUT: (firefox:2478): GLib-GObject-CRITICAL **: g_type_add_interface_static: assertion `g_type_parent (interface_type) == G_TYPE_INTERFACE' failed 12:59:05 INFO - 2015-11-23 12:59:05,837 DEBUG : BROWSER_OUTPUT: 12:59:05 INFO - 2015-11-23 12:59:05,837 DEBUG : BROWSER_OUTPUT: (firefox:2478): GLib-GObject-CRITICAL **: g_type_add_interface_static: assertion `g_type_parent (interface_type) == G_TYPE_INTERFACE' failed 12:59:05 INFO - 2015-11-23 12:59:05,898 DEBUG : BROWSER_OUTPUT: 12:59:05 INFO - 2015-11-23 12:59:05,898 DEBUG : BROWSER_OUTPUT: (firefox:2478): GLib-GObject-CRITICAL **: g_type_add_interface_static: assertion `g_type_parent (interface_type) == G_TYPE_INTERFACE' failed 12:59:06 INFO - 2015-11-23 12:59:06,329 DEBUG : BROWSER_OUTPUT: RSS: Main: 146583552 12:59:06 INFO - 2015-11-23 12:59:06,329 DEBUG : BROWSER_OUTPUT: 12:59:07 INFO - 2015-11-23 12:59:07,725 DEBUG : BROWSER_OUTPUT: Cycle 1(2): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:08 INFO - 2015-11-23 12:59:08,427 DEBUG : BROWSER_OUTPUT: RSS: Main: 145776640 12:59:08 INFO - 2015-11-23 12:59:08,427 DEBUG : BROWSER_OUTPUT: 12:59:09 INFO - 2015-11-23 12:59:09,771 DEBUG : BROWSER_OUTPUT: Cycle 1(3): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:10 INFO - 2015-11-23 12:59:10,473 DEBUG : BROWSER_OUTPUT: RSS: Main: 144707584 12:59:10 INFO - 2015-11-23 12:59:10,473 DEBUG : BROWSER_OUTPUT: 12:59:11 INFO - 2015-11-23 12:59:11,843 DEBUG : BROWSER_OUTPUT: Cycle 1(4): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:12 INFO - 2015-11-23 12:59:12,537 DEBUG : BROWSER_OUTPUT: RSS: Main: 144879616 12:59:12 INFO - 2015-11-23 12:59:12,537 DEBUG : BROWSER_OUTPUT: 12:59:13 INFO - 2015-11-23 12:59:13,933 DEBUG : BROWSER_OUTPUT: Cycle 1(5): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:14 INFO - 2015-11-23 12:59:14,639 DEBUG : BROWSER_OUTPUT: RSS: Main: 142012416 12:59:14 INFO - 2015-11-23 12:59:14,640 DEBUG : BROWSER_OUTPUT: 12:59:15 INFO - 2015-11-23 12:59:15,996 DEBUG : BROWSER_OUTPUT: Cycle 1(6): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:16 INFO - 2015-11-23 12:59:16,702 DEBUG : BROWSER_OUTPUT: RSS: Main: 142000128 12:59:16 INFO - 2015-11-23 12:59:16,703 DEBUG : BROWSER_OUTPUT: 12:59:18 INFO - 2015-11-23 12:59:18,098 DEBUG : BROWSER_OUTPUT: Cycle 1(7): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:18 INFO - 2015-11-23 12:59:18,805 DEBUG : BROWSER_OUTPUT: RSS: Main: 142180352 12:59:18 INFO - 2015-11-23 12:59:18,805 DEBUG : BROWSER_OUTPUT: 12:59:20 INFO - 2015-11-23 12:59:20,195 DEBUG : BROWSER_OUTPUT: Cycle 1(8): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:20 INFO - 2015-11-23 12:59:20,898 DEBUG : BROWSER_OUTPUT: RSS: Main: 141864960 12:59:20 INFO - 2015-11-23 12:59:20,898 DEBUG : BROWSER_OUTPUT: 12:59:22 INFO - 2015-11-23 12:59:22,262 DEBUG : BROWSER_OUTPUT: Cycle 1(9): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:22 INFO - 2015-11-23 12:59:22,963 DEBUG : BROWSER_OUTPUT: RSS: Main: 141971456 12:59:22 INFO - 2015-11-23 12:59:22,963 DEBUG : BROWSER_OUTPUT: 12:59:24 INFO - 2015-11-23 12:59:24,339 DEBUG : BROWSER_OUTPUT: Cycle 1(10): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:25 INFO - 2015-11-23 12:59:25,041 DEBUG : BROWSER_OUTPUT: RSS: Main: 142151680 12:59:25 INFO - 2015-11-23 12:59:25,041 DEBUG : BROWSER_OUTPUT: 12:59:26 INFO - 2015-11-23 12:59:26,413 DEBUG : BROWSER_OUTPUT: Cycle 1(11): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:27 INFO - 2015-11-23 12:59:27,114 DEBUG : BROWSER_OUTPUT: RSS: Main: 141922304 12:59:27 INFO - 2015-11-23 12:59:27,114 DEBUG : BROWSER_OUTPUT: 12:59:28 INFO - 2015-11-23 12:59:28,498 DEBUG : BROWSER_OUTPUT: Cycle 1(12): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:29 INFO - 2015-11-23 12:59:29,208 DEBUG : BROWSER_OUTPUT: RSS: Main: 142737408 12:59:29 INFO - 2015-11-23 12:59:29,208 DEBUG : BROWSER_OUTPUT: 12:59:30 INFO - 2015-11-23 12:59:30,556 DEBUG : BROWSER_OUTPUT: Cycle 1(13): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:31 INFO - 2015-11-23 12:59:31,267 DEBUG : BROWSER_OUTPUT: RSS: Main: 142409728 12:59:31 INFO - 2015-11-23 12:59:31,267 DEBUG : BROWSER_OUTPUT: 12:59:32 INFO - 2015-11-23 12:59:32,631 DEBUG : BROWSER_OUTPUT: Cycle 1(14): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:33 INFO - 2015-11-23 12:59:33,332 DEBUG : BROWSER_OUTPUT: RSS: Main: 142225408 12:59:33 INFO - 2015-11-23 12:59:33,332 DEBUG : BROWSER_OUTPUT: 12:59:34 INFO - 2015-11-23 12:59:34,716 DEBUG : BROWSER_OUTPUT: Cycle 1(15): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:35 INFO - 2015-11-23 12:59:35,478 DEBUG : BROWSER_OUTPUT: RSS: Main: 141697024 12:59:35 INFO - 2015-11-23 12:59:35,479 DEBUG : BROWSER_OUTPUT: 12:59:36 INFO - 2015-11-23 12:59:36,829 DEBUG : BROWSER_OUTPUT: Cycle 1(16): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:37 INFO - 2015-11-23 12:59:37,530 DEBUG : BROWSER_OUTPUT: RSS: Main: 143818752 12:59:37 INFO - 2015-11-23 12:59:37,531 DEBUG : BROWSER_OUTPUT: 12:59:38 INFO - 2015-11-23 12:59:38,899 DEBUG : BROWSER_OUTPUT: Cycle 1(17): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:39 INFO - 2015-11-23 12:59:39,601 DEBUG : BROWSER_OUTPUT: RSS: Main: 143937536 12:59:39 INFO - 2015-11-23 12:59:39,601 DEBUG : BROWSER_OUTPUT: 12:59:40 INFO - 2015-11-23 12:59:40,991 DEBUG : BROWSER_OUTPUT: Cycle 1(18): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:41 INFO - 2015-11-23 12:59:41,704 DEBUG : BROWSER_OUTPUT: RSS: Main: 143896576 12:59:41 INFO - 2015-11-23 12:59:41,705 DEBUG : BROWSER_OUTPUT: 12:59:43 INFO - 2015-11-23 12:59:43,089 DEBUG : BROWSER_OUTPUT: Cycle 1(19): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:43 INFO - 2015-11-23 12:59:43,783 DEBUG : BROWSER_OUTPUT: RSS: Main: 143699968 12:59:43 INFO - 2015-11-23 12:59:43,783 DEBUG : BROWSER_OUTPUT: 12:59:45 INFO - 2015-11-23 12:59:45,147 DEBUG : BROWSER_OUTPUT: Cycle 1(20): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:45 INFO - 2015-11-23 12:59:45,848 DEBUG : BROWSER_OUTPUT: RSS: Main: 143716352 12:59:45 INFO - 2015-11-23 12:59:45,849 DEBUG : BROWSER_OUTPUT: 12:59:47 INFO - 2015-11-23 12:59:47,420 DEBUG : BROWSER_OUTPUT: Cycle 1(21): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:48 INFO - 2015-11-23 12:59:48,127 DEBUG : BROWSER_OUTPUT: RSS: Main: 143757312 12:59:48 INFO - 2015-11-23 12:59:48,127 DEBUG : BROWSER_OUTPUT: 12:59:49 INFO - 2015-11-23 12:59:49,511 DEBUG : BROWSER_OUTPUT: Cycle 1(22): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:50 INFO - 2015-11-23 12:59:50,217 DEBUG : BROWSER_OUTPUT: RSS: Main: 143855616 12:59:50 INFO - 2015-11-23 12:59:50,218 DEBUG : BROWSER_OUTPUT: 12:59:51 INFO - 2015-11-23 12:59:51,602 DEBUG : BROWSER_OUTPUT: Cycle 1(23): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:52 INFO - 2015-11-23 12:59:52,304 DEBUG : BROWSER_OUTPUT: RSS: Main: 142450688 12:59:52 INFO - 2015-11-23 12:59:52,304 DEBUG : BROWSER_OUTPUT: 12:59:53 INFO - 2015-11-23 12:59:53,709 DEBUG : BROWSER_OUTPUT: Cycle 1(24): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:54 INFO - 2015-11-23 12:59:54,093 DEBUG : BROWSER_OUTPUT: 1448312394089 addons.productaddons ERROR Request failed certificate checks: [Exception... "SSL is required and URI scheme is not https." nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)" location: "JS frame :: resource://gre/modules/CertUtils.jsm :: checkCert :: line 145" data: no] 12:59:54 INFO - 2015-11-23 12:59:54,443 DEBUG : BROWSER_OUTPUT: RSS: Main: 151007232 12:59:54 INFO - 2015-11-23 12:59:54,443 DEBUG : BROWSER_OUTPUT: 12:59:56 INFO - 2015-11-23 12:59:56,050 DEBUG : BROWSER_OUTPUT: Cycle 1(25): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html) 12:59:56 INFO - 2015-11-23 12:59:56,778 DEBUG : BROWSER_OUTPUT: RSS: Main: 156987392 12:59:56 INFO - 2015-11-23 12:59:56,778 DEBUG : BROWSER_OUTPUT: 12:59:57 INFO - 2015-11-23 12:59:57,176 DEBUG : BROWSER_OUTPUT: 12:59:57 INFO - 2015-11-23 12:59:57,176 DEBUG : BROWSER_OUTPUT: (firefox:2478): GLib-GObject-CRITICAL **: g_type_add_interface_static: assertion `g_type_parent (interface_type) == G_TYPE_INTERFACE' failed 12:59:57 INFO - 2015-11-23 12:59:57,781 DEBUG : BROWSER_OUTPUT: Cycle 1(1): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 12:59:58 INFO - 2015-11-23 12:59:58,370 DEBUG : BROWSER_OUTPUT: RSS: Main: 152449024 12:59:58 INFO - 2015-11-23 12:59:58,370 DEBUG : BROWSER_OUTPUT: 12:59:59 INFO - 2015-11-23 12:59:59,296 DEBUG : BROWSER_OUTPUT: Cycle 1(2): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 12:59:59 INFO - 2015-11-23 12:59:59,902 DEBUG : BROWSER_OUTPUT: RSS: Main: 151150592 12:59:59 INFO - 2015-11-23 12:59:59,902 DEBUG : BROWSER_OUTPUT: 13:00:00 INFO - 2015-11-23 13:00:00,824 DEBUG : BROWSER_OUTPUT: Cycle 1(3): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:01 INFO - 2015-11-23 13:00:01,430 DEBUG : BROWSER_OUTPUT: RSS: Main: 149970944 13:00:01 INFO - 2015-11-23 13:00:01,430 DEBUG : BROWSER_OUTPUT: 13:00:02 INFO - 2015-11-23 13:00:02,351 DEBUG : BROWSER_OUTPUT: Cycle 1(4): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:02 INFO - 2015-11-23 13:00:02,953 DEBUG : BROWSER_OUTPUT: RSS: Main: 148819968 13:00:02 INFO - 2015-11-23 13:00:02,953 DEBUG : BROWSER_OUTPUT: 13:00:03 INFO - 2015-11-23 13:00:03,874 DEBUG : BROWSER_OUTPUT: Cycle 1(5): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:04 INFO - 2015-11-23 13:00:04,476 DEBUG : BROWSER_OUTPUT: RSS: Main: 142741504 13:00:04 INFO - 2015-11-23 13:00:04,476 DEBUG : BROWSER_OUTPUT: 13:00:05 INFO - 2015-11-23 13:00:05,422 DEBUG : BROWSER_OUTPUT: Cycle 1(6): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:06 INFO - 2015-11-23 13:00:06,024 DEBUG : BROWSER_OUTPUT: RSS: Main: 140627968 13:00:06 INFO - 2015-11-23 13:00:06,024 DEBUG : BROWSER_OUTPUT: 13:00:06 INFO - 2015-11-23 13:00:06,945 DEBUG : BROWSER_OUTPUT: Cycle 1(7): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:07 INFO - 2015-11-23 13:00:07,551 DEBUG : BROWSER_OUTPUT: RSS: Main: 140419072 13:00:07 INFO - 2015-11-23 13:00:07,551 DEBUG : BROWSER_OUTPUT: 13:00:08 INFO - 2015-11-23 13:00:08,485 DEBUG : BROWSER_OUTPUT: Cycle 1(8): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:09 INFO - 2015-11-23 13:00:09,086 DEBUG : BROWSER_OUTPUT: RSS: Main: 141279232 13:00:09 INFO - 2015-11-23 13:00:09,087 DEBUG : BROWSER_OUTPUT: 13:00:09 INFO - 2015-11-23 13:00:09,993 DEBUG : BROWSER_OUTPUT: Cycle 1(9): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:10 INFO - 2015-11-23 13:00:10,594 DEBUG : BROWSER_OUTPUT: RSS: Main: 139538432 13:00:10 INFO - 2015-11-23 13:00:10,594 DEBUG : BROWSER_OUTPUT: 13:00:11 INFO - 2015-11-23 13:00:11,516 DEBUG : BROWSER_OUTPUT: Cycle 1(10): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:12 INFO - 2015-11-23 13:00:12,119 DEBUG : BROWSER_OUTPUT: RSS: Main: 139526144 13:00:12 INFO - 2015-11-23 13:00:12,119 DEBUG : BROWSER_OUTPUT: 13:00:13 INFO - 2015-11-23 13:00:13,041 DEBUG : BROWSER_OUTPUT: Cycle 1(11): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:13 INFO - 2015-11-23 13:00:13,642 DEBUG : BROWSER_OUTPUT: RSS: Main: 139599872 13:00:13 INFO - 2015-11-23 13:00:13,642 DEBUG : BROWSER_OUTPUT: 13:00:14 INFO - 2015-11-23 13:00:14,570 DEBUG : BROWSER_OUTPUT: Cycle 1(12): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:15 INFO - 2015-11-23 13:00:15,171 DEBUG : BROWSER_OUTPUT: RSS: Main: 141209600 13:00:15 INFO - 2015-11-23 13:00:15,171 DEBUG : BROWSER_OUTPUT: 13:00:16 INFO - 2015-11-23 13:00:16,093 DEBUG : BROWSER_OUTPUT: Cycle 1(13): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:16 INFO - 2015-11-23 13:00:16,694 DEBUG : BROWSER_OUTPUT: RSS: Main: 139300864 13:00:16 INFO - 2015-11-23 13:00:16,694 DEBUG : BROWSER_OUTPUT: 13:00:17 INFO - 2015-11-23 13:00:17,636 DEBUG : BROWSER_OUTPUT: Cycle 1(14): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:18 INFO - 2015-11-23 13:00:18,237 DEBUG : BROWSER_OUTPUT: RSS: Main: 141520896 13:00:18 INFO - 2015-11-23 13:00:18,238 DEBUG : BROWSER_OUTPUT: 13:00:19 INFO - 2015-11-23 13:00:19,159 DEBUG : BROWSER_OUTPUT: Cycle 1(15): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:19 INFO - 2015-11-23 13:00:19,765 DEBUG : BROWSER_OUTPUT: RSS: Main: 139350016 13:00:19 INFO - 2015-11-23 13:00:19,765 DEBUG : BROWSER_OUTPUT: 13:00:20 INFO - 2015-11-23 13:00:20,699 DEBUG : BROWSER_OUTPUT: Cycle 1(16): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:21 INFO - 2015-11-23 13:00:21,300 DEBUG : BROWSER_OUTPUT: RSS: Main: 139149312 13:00:21 INFO - 2015-11-23 13:00:21,300 DEBUG : BROWSER_OUTPUT: 13:00:22 INFO - 2015-11-23 13:00:22,227 DEBUG : BROWSER_OUTPUT: Cycle 1(17): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:22 INFO - 2015-11-23 13:00:22,828 DEBUG : BROWSER_OUTPUT: RSS: Main: 140292096 13:00:22 INFO - 2015-11-23 13:00:22,828 DEBUG : BROWSER_OUTPUT: 13:00:23 INFO - 2015-11-23 13:00:23,741 DEBUG : BROWSER_OUTPUT: Cycle 1(18): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:24 INFO - 2015-11-23 13:00:24,355 DEBUG : BROWSER_OUTPUT: RSS: Main: 141094912 13:00:24 INFO - 2015-11-23 13:00:24,355 DEBUG : BROWSER_OUTPUT: 13:00:25 INFO - 2015-11-23 13:00:25,277 DEBUG : BROWSER_OUTPUT: Cycle 1(19): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:25 INFO - 2015-11-23 13:00:25,883 DEBUG : BROWSER_OUTPUT: RSS: Main: 142278656 13:00:25 INFO - 2015-11-23 13:00:25,883 DEBUG : BROWSER_OUTPUT: 13:00:26 INFO - 2015-11-23 13:00:26,817 DEBUG : BROWSER_OUTPUT: Cycle 1(20): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:27 INFO - 2015-11-23 13:00:27,418 DEBUG : BROWSER_OUTPUT: RSS: Main: 142295040 13:00:27 INFO - 2015-11-23 13:00:27,418 DEBUG : BROWSER_OUTPUT: 13:00:28 INFO - 2015-11-23 13:00:28,327 DEBUG : BROWSER_OUTPUT: Cycle 1(21): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:28 INFO - 2015-11-23 13:00:28,933 DEBUG : BROWSER_OUTPUT: RSS: Main: 140144640 13:00:28 INFO - 2015-11-23 13:00:28,933 DEBUG : BROWSER_OUTPUT: 13:00:29 INFO - 2015-11-23 13:00:29,846 DEBUG : BROWSER_OUTPUT: Cycle 1(22): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:30 INFO - 2015-11-23 13:00:30,448 DEBUG : BROWSER_OUTPUT: RSS: Main: 142516224 13:00:30 INFO - 2015-11-23 13:00:30,448 DEBUG : BROWSER_OUTPUT: 13:00:31 INFO - 2015-11-23 13:00:31,390 DEBUG : BROWSER_OUTPUT: Cycle 1(23): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:31 INFO - 2015-11-23 13:00:31,997 DEBUG : BROWSER_OUTPUT: RSS: Main: 140259328 13:00:31 INFO - 2015-11-23 13:00:31,998 DEBUG : BROWSER_OUTPUT: 13:00:32 INFO - 2015-11-23 13:00:32,924 DEBUG : BROWSER_OUTPUT: Cycle 1(24): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:33 INFO - 2015-11-23 13:00:33,530 DEBUG : BROWSER_OUTPUT: RSS: Main: 142139392 13:00:33 INFO - 2015-11-23 13:00:33,530 DEBUG : BROWSER_OUTPUT: 13:00:34 INFO - 2015-11-23 13:00:34,460 DEBUG : BROWSER_OUTPUT: Cycle 1(25): loaded file:///builds/slave/test/build/tests/talos/talos/tests/a11y/tablemutation.html (next: file:///builds/slave/test/build/tests/talos/talos/tests/a11y/dhtml.html) 13:00:34 INFO - 2015-11-23 13:00:34,710 DEBUG : BROWSER_OUTPUT: RSS: Main: 140910592 13:00:34 INFO - 2015-11-23 13:00:34,710 DEBUG : BROWSER_OUTPUT: 13:00:34 INFO - 2015-11-23 13:00:34,712 DEBUG : BROWSER_OUTPUT: __start_tp_report 13:00:34 INFO - 2015-11-23 13:00:34,712 DEBUG : BROWSER_OUTPUT: _x_x_mozilla_page_load 13:00:34 INFO - 2015-11-23 13:00:34,712 DEBUG : BROWSER_OUTPUT: _x_x_mozilla_page_load_details 13:00:34 INFO - 2015-11-23 13:00:34,712 DEBUG : BROWSER_OUTPUT: |i|pagename|runs| 13:00:34 INFO - 2015-11-23 13:00:34,712 DEBUG : BROWSER_OUTPUT: |0;dhtml.html;1243;1294;1291;1294;1312;1308;1317;1306;1299;1307;1309;1302;1302;1312;1310;1301;1298;1305;1303;1306;1524;1301;1305;1319;1550 13:00:34 INFO - 2015-11-23 13:00:34,712 DEBUG : BROWSER_OUTPUT: |1;tablemutation.html;379;382;395;386;388;394;383;384;374;385;380;393;388;385;376;385;391;379;393;376;381;386;387;387;384 13:00:34 INFO - 2015-11-23 13:00:34,712 DEBUG : BROWSER_OUTPUT: __end_tp_report 13:00:34 INFO - 2015-11-23 13:00:34,713 DEBUG : BROWSER_OUTPUT: __start_cc_report 13:00:34 INFO - 2015-11-23 13:00:34,713 DEBUG : BROWSER_OUTPUT: _x_x_mozilla_cycle_collect,2801 13:00:34 INFO - 2015-11-23 13:00:34,713 DEBUG : BROWSER_OUTPUT: __end_cc_report 13:00:34 INFO - 2015-11-23 13:00:34,713 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312434710__endTimestamp 13:00:34 INFO - 2015-11-23 13:00:34,713 DEBUG : BROWSER_OUTPUT: 13:00:34 INFO - 2015-11-23 13:00:34,714 DEBUG : BROWSER_OUTPUT: ------- Summary: start ------- 13:00:34 INFO - 2015-11-23 13:00:34,715 DEBUG : BROWSER_OUTPUT: Number of tests: 2 13:00:34 INFO - 2015-11-23 13:00:34,715 DEBUG : BROWSER_OUTPUT: 13:00:34 INFO - 2015-11-23 13:00:34,715 DEBUG : BROWSER_OUTPUT: [#0] dhtml.html Cycles:25 Average:1320.72 Median:1305.00 stddev:66.68 (5.1%) stddev-sans-first:66.08 13:00:34 INFO - 2015-11-23 13:00:34,715 DEBUG : BROWSER_OUTPUT: Values: 1243.0 1294.0 1291.0 1294.0 1312.0 1308.0 1317.0 1306.0 1299.0 1307.0 1309.0 1302.0 1302.0 1312.0 1310.0 1301.0 1298.0 1305.0 1303.0 1306.0 1524.0 1301.0 1305.0 1319.0 1550.0 13:00:34 INFO - 2015-11-23 13:00:34,715 DEBUG : BROWSER_OUTPUT: 13:00:34 INFO - 2015-11-23 13:00:34,715 DEBUG : BROWSER_OUTPUT: [#1] tablemutation.html Cycles:25 Average:384.84 Median:385.00 stddev:5.71 (1.5%) stddev-sans-first:5.70 13:00:34 INFO - 2015-11-23 13:00:34,715 DEBUG : BROWSER_OUTPUT: Values: 379.0 382.0 395.0 386.0 388.0 394.0 383.0 384.0 374.0 385.0 380.0 393.0 388.0 385.0 376.0 385.0 391.0 379.0 393.0 376.0 381.0 386.0 387.0 387.0 384.0 13:00:34 INFO - 2015-11-23 13:00:34,716 DEBUG : BROWSER_OUTPUT: -------- Summary: end -------- 13:00:34 INFO - 2015-11-23 13:00:34,716 DEBUG : BROWSER_OUTPUT: 13:00:35 INFO - 2015-11-23 13:00:35,437 INFO : Browser exited with error code: 0 13:00:35 INFO - 2015-11-23 13:00:35,456 INFO : Completed test a11yr (00:01:48) 13:00:35 INFO - 2015-11-23 13:00:35,456 INFO : Starting test ts_paint 13:00:35 INFO - 2015-11-23 13:00:35,456 DEBUG : operating with platform_type : linux_ 13:00:35 INFO - 2015-11-23 13:00:35,456 INFO : Initialising browser for ts_paint test... 13:00:35 INFO - 2015-11-23 13:00:35,462 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/getInfo.html 13:00:39 INFO - 2015-11-23 13:00:39,809 DEBUG : BROWSER_OUTPUT: __metrics Screen width/height:1600/1200 13:00:39 INFO - 2015-11-23 13:00:39,809 DEBUG : BROWSER_OUTPUT: colorDepth:24 13:00:39 INFO - 2015-11-23 13:00:39,809 DEBUG : BROWSER_OUTPUT: Browser inner width/height: 1024/697 13:00:39 INFO - 2015-11-23 13:00:39,809 DEBUG : BROWSER_OUTPUT: __metrics 13:00:40 INFO - 2015-11-23 13:00:40,825 INFO : Browser initialized. 13:00:40 INFO - 2015-11-23 13:00:40,826 INFO : Running cycle 1/20 for ts_paint test... 13:00:40 INFO - 2015-11-23 13:00:40,826 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:00:42 INFO - 2015-11-23 13:00:42,969 DEBUG : BROWSER_OUTPUT: __start_report499__end_report 13:00:42 INFO - 2015-11-23 13:00:42,969 DEBUG : BROWSER_OUTPUT: 13:00:42 INFO - 2015-11-23 13:00:42,985 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312442980__endTimestamp 13:00:43 INFO - 2015-11-23 13:00:43,877 INFO : Browser exited with error code: 0 13:00:43 INFO - 2015-11-23 13:00:43,879 INFO : Running cycle 2/20 for ts_paint test... 13:00:43 INFO - 2015-11-23 13:00:43,879 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:00:45 INFO - 2015-11-23 13:00:45,472 DEBUG : BROWSER_OUTPUT: __start_report538__end_report 13:00:45 INFO - 2015-11-23 13:00:45,473 DEBUG : BROWSER_OUTPUT: 13:00:45 INFO - 2015-11-23 13:00:45,489 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312445481__endTimestamp 13:00:46 INFO - 2015-11-23 13:00:46,345 INFO : Browser exited with error code: 0 13:00:46 INFO - 2015-11-23 13:00:46,347 INFO : Running cycle 3/20 for ts_paint test... 13:00:46 INFO - 2015-11-23 13:00:46,347 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:00:48 INFO - 2015-11-23 13:00:48,025 DEBUG : BROWSER_OUTPUT: __start_report572__end_report 13:00:48 INFO - 2015-11-23 13:00:48,025 DEBUG : BROWSER_OUTPUT: 13:00:48 INFO - 2015-11-23 13:00:48,033 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312448030__endTimestamp 13:00:48 INFO - 2015-11-23 13:00:48,953 INFO : Browser exited with error code: 0 13:00:48 INFO - 2015-11-23 13:00:48,955 INFO : Running cycle 4/20 for ts_paint test... 13:00:48 INFO - 2015-11-23 13:00:48,955 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:00:50 INFO - 2015-11-23 13:00:50,597 DEBUG : BROWSER_OUTPUT: __start_report587__end_report 13:00:50 INFO - 2015-11-23 13:00:50,597 DEBUG : BROWSER_OUTPUT: 13:00:50 INFO - 2015-11-23 13:00:50,613 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312450606__endTimestamp 13:00:51 INFO - 2015-11-23 13:00:51,601 INFO : Browser exited with error code: 0 13:00:51 INFO - 2015-11-23 13:00:51,603 INFO : Running cycle 5/20 for ts_paint test... 13:00:51 INFO - 2015-11-23 13:00:51,603 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:00:53 INFO - 2015-11-23 13:00:53,200 DEBUG : BROWSER_OUTPUT: __start_report498__end_report 13:00:53 INFO - 2015-11-23 13:00:53,201 DEBUG : BROWSER_OUTPUT: 13:00:53 INFO - 2015-11-23 13:00:53,208 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312453206__endTimestamp 13:00:54 INFO - 2015-11-23 13:00:54,213 INFO : Browser exited with error code: 0 13:00:54 INFO - 2015-11-23 13:00:54,215 INFO : Running cycle 6/20 for ts_paint test... 13:00:54 INFO - 2015-11-23 13:00:54,215 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:00:55 INFO - 2015-11-23 13:00:55,897 DEBUG : BROWSER_OUTPUT: __start_report562__end_report 13:00:55 INFO - 2015-11-23 13:00:55,897 DEBUG : BROWSER_OUTPUT: 13:00:55 INFO - 2015-11-23 13:00:55,913 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312455907__endTimestamp 13:00:56 INFO - 2015-11-23 13:00:56,925 INFO : Browser exited with error code: 0 13:00:56 INFO - 2015-11-23 13:00:56,927 INFO : Running cycle 7/20 for ts_paint test... 13:00:56 INFO - 2015-11-23 13:00:56,927 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:00:58 INFO - 2015-11-23 13:00:58,540 DEBUG : BROWSER_OUTPUT: __start_report537__end_report 13:00:58 INFO - 2015-11-23 13:00:58,540 DEBUG : BROWSER_OUTPUT: 13:00:58 INFO - 2015-11-23 13:00:58,547 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312458544__endTimestamp 13:00:59 INFO - 2015-11-23 13:00:59,557 INFO : Browser exited with error code: 0 13:00:59 INFO - 2015-11-23 13:00:59,559 INFO : Running cycle 8/20 for ts_paint test... 13:00:59 INFO - 2015-11-23 13:00:59,559 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:01 INFO - 2015-11-23 13:01:01,143 DEBUG : BROWSER_OUTPUT: __start_report494__end_report 13:01:01 INFO - 2015-11-23 13:01:01,143 DEBUG : BROWSER_OUTPUT: 13:01:01 INFO - 2015-11-23 13:01:01,144 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312461144__endTimestamp 13:01:02 INFO - 2015-11-23 13:01:02,118 INFO : Browser exited with error code: 0 13:01:02 INFO - 2015-11-23 13:01:02,119 INFO : Running cycle 9/20 for ts_paint test... 13:01:02 INFO - 2015-11-23 13:01:02,119 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:03 INFO - 2015-11-23 13:01:03,751 DEBUG : BROWSER_OUTPUT: __start_report535__end_report 13:01:03 INFO - 2015-11-23 13:01:03,752 DEBUG : BROWSER_OUTPUT: 13:01:03 INFO - 2015-11-23 13:01:03,755 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312463754__endTimestamp 13:01:04 INFO - 2015-11-23 13:01:04,742 INFO : Browser exited with error code: 0 13:01:04 INFO - 2015-11-23 13:01:04,743 INFO : Running cycle 10/20 for ts_paint test... 13:01:04 INFO - 2015-11-23 13:01:04,743 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:06 INFO - 2015-11-23 13:01:06,355 DEBUG : BROWSER_OUTPUT: __start_report540__end_report 13:01:06 INFO - 2015-11-23 13:01:06,356 DEBUG : BROWSER_OUTPUT: 13:01:06 INFO - 2015-11-23 13:01:06,372 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312466366__endTimestamp 13:01:07 INFO - 2015-11-23 13:01:07,429 INFO : Browser exited with error code: 0 13:01:07 INFO - 2015-11-23 13:01:07,431 INFO : Running cycle 11/20 for ts_paint test... 13:01:07 INFO - 2015-11-23 13:01:07,431 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:09 INFO - 2015-11-23 13:01:09,016 DEBUG : BROWSER_OUTPUT: __start_report498__end_report 13:01:09 INFO - 2015-11-23 13:01:09,016 DEBUG : BROWSER_OUTPUT: 13:01:09 INFO - 2015-11-23 13:01:09,023 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312469022__endTimestamp 13:01:10 INFO - 2015-11-23 13:01:10,038 INFO : Browser exited with error code: 0 13:01:10 INFO - 2015-11-23 13:01:10,039 INFO : Running cycle 12/20 for ts_paint test... 13:01:10 INFO - 2015-11-23 13:01:10,039 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:11 INFO - 2015-11-23 13:01:11,592 DEBUG : BROWSER_OUTPUT: __start_report496__end_report 13:01:11 INFO - 2015-11-23 13:01:11,593 DEBUG : BROWSER_OUTPUT: 13:01:11 INFO - 2015-11-23 13:01:11,594 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312471593__endTimestamp 13:01:12 INFO - 2015-11-23 13:01:12,665 INFO : Browser exited with error code: 0 13:01:12 INFO - 2015-11-23 13:01:12,667 INFO : Running cycle 13/20 for ts_paint test... 13:01:12 INFO - 2015-11-23 13:01:12,667 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:14 INFO - 2015-11-23 13:01:14,225 DEBUG : BROWSER_OUTPUT: __start_report504__end_report 13:01:14 INFO - 2015-11-23 13:01:14,225 DEBUG : BROWSER_OUTPUT: 13:01:14 INFO - 2015-11-23 13:01:14,226 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312474226__endTimestamp 13:01:15 INFO - 2015-11-23 13:01:15,273 INFO : Browser exited with error code: 0 13:01:15 INFO - 2015-11-23 13:01:15,275 INFO : Running cycle 14/20 for ts_paint test... 13:01:15 INFO - 2015-11-23 13:01:15,275 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:16 INFO - 2015-11-23 13:01:16,853 DEBUG : BROWSER_OUTPUT: __start_report519__end_report 13:01:16 INFO - 2015-11-23 13:01:16,853 DEBUG : BROWSER_OUTPUT: 13:01:16 INFO - 2015-11-23 13:01:16,869 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312476864__endTimestamp 13:01:17 INFO - 2015-11-23 13:01:17,934 INFO : Browser exited with error code: 0 13:01:17 INFO - 2015-11-23 13:01:17,935 INFO : Running cycle 15/20 for ts_paint test... 13:01:17 INFO - 2015-11-23 13:01:17,935 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:19 INFO - 2015-11-23 13:01:19,513 DEBUG : BROWSER_OUTPUT: __start_report547__end_report 13:01:19 INFO - 2015-11-23 13:01:19,513 DEBUG : BROWSER_OUTPUT: 13:01:19 INFO - 2015-11-23 13:01:19,520 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312479519__endTimestamp 13:01:20 INFO - 2015-11-23 13:01:20,589 INFO : Browser exited with error code: 0 13:01:20 INFO - 2015-11-23 13:01:20,591 INFO : Running cycle 16/20 for ts_paint test... 13:01:20 INFO - 2015-11-23 13:01:20,591 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:22 INFO - 2015-11-23 13:01:22,207 DEBUG : BROWSER_OUTPUT: __start_report538__end_report 13:01:22 INFO - 2015-11-23 13:01:22,207 DEBUG : BROWSER_OUTPUT: 13:01:22 INFO - 2015-11-23 13:01:22,215 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312482212__endTimestamp 13:01:23 INFO - 2015-11-23 13:01:23,257 INFO : Browser exited with error code: 0 13:01:23 INFO - 2015-11-23 13:01:23,259 INFO : Running cycle 17/20 for ts_paint test... 13:01:23 INFO - 2015-11-23 13:01:23,259 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:24 INFO - 2015-11-23 13:01:24,856 DEBUG : BROWSER_OUTPUT: __start_report537__end_report 13:01:24 INFO - 2015-11-23 13:01:24,857 DEBUG : BROWSER_OUTPUT: 13:01:24 INFO - 2015-11-23 13:01:24,872 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312484865__endTimestamp 13:01:25 INFO - 2015-11-23 13:01:25,989 INFO : Browser exited with error code: 0 13:01:25 INFO - 2015-11-23 13:01:25,991 INFO : Running cycle 18/20 for ts_paint test... 13:01:25 INFO - 2015-11-23 13:01:25,991 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:27 INFO - 2015-11-23 13:01:27,611 DEBUG : BROWSER_OUTPUT: __start_report543__end_report 13:01:27 INFO - 2015-11-23 13:01:27,611 DEBUG : BROWSER_OUTPUT: 13:01:27 INFO - 2015-11-23 13:01:27,619 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312487618__endTimestamp 13:01:28 INFO - 2015-11-23 13:01:28,701 INFO : Browser exited with error code: 0 13:01:28 INFO - 2015-11-23 13:01:28,703 INFO : Running cycle 19/20 for ts_paint test... 13:01:28 INFO - 2015-11-23 13:01:28,703 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:30 INFO - 2015-11-23 13:01:30,337 DEBUG : BROWSER_OUTPUT: __start_report528__end_report 13:01:30 INFO - 2015-11-23 13:01:30,337 DEBUG : BROWSER_OUTPUT: 13:01:30 INFO - 2015-11-23 13:01:30,341 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312490340__endTimestamp 13:01:31 INFO - 2015-11-23 13:01:31,365 INFO : Browser exited with error code: 0 13:01:31 INFO - 2015-11-23 13:01:31,367 INFO : Running cycle 20/20 for ts_paint test... 13:01:31 INFO - 2015-11-23 13:01:31,367 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpqCJSBw/profile http://localhost:53751/startup_test/tspaint_test.html 13:01:32 INFO - 2015-11-23 13:01:32,991 DEBUG : BROWSER_OUTPUT: __start_report504__end_report 13:01:32 INFO - 2015-11-23 13:01:32,991 DEBUG : BROWSER_OUTPUT: 13:01:32 INFO - 2015-11-23 13:01:32,999 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312492997__endTimestamp 13:01:34 INFO - 2015-11-23 13:01:34,085 INFO : Browser exited with error code: 0 13:01:34 INFO - 2015-11-23 13:01:34,104 INFO : Completed test ts_paint (00:00:58) 13:01:34 INFO - 2015-11-23 13:01:34,104 INFO : Starting test tpaint 13:01:34 INFO - 2015-11-23 13:01:34,104 DEBUG : operating with platform_type : linux_ 13:01:34 INFO - 2015-11-23 13:01:34,105 INFO : Initialising browser for tpaint test... 13:01:34 INFO - 2015-11-23 13:01:34,111 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpvm3TDY/profile http://localhost:53751/getInfo.html 13:01:38 INFO - 2015-11-23 13:01:38,317 DEBUG : BROWSER_OUTPUT: __metrics Screen width/height:1600/1200 13:01:38 INFO - 2015-11-23 13:01:38,317 DEBUG : BROWSER_OUTPUT: colorDepth:24 13:01:38 INFO - 2015-11-23 13:01:38,317 DEBUG : BROWSER_OUTPUT: Browser inner width/height: 1024/697 13:01:38 INFO - 2015-11-23 13:01:38,317 DEBUG : BROWSER_OUTPUT: __metrics 13:01:39 INFO - 2015-11-23 13:01:39,265 INFO : Browser initialized. 13:01:39 INFO - 2015-11-23 13:01:39,266 INFO : Running cycle 1/1 for tpaint test... 13:01:39 INFO - 2015-11-23 13:01:39,266 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpvm3TDY/profile file:///builds/slave/test/build/tests/talos/talos/startup_test/tpaint.html?auto=1 13:02:07 INFO - 2015-11-23 13:02:07,441 DEBUG : BROWSER_OUTPUT: __start_report228.32500000000073|243.3050000000003|256.90499999999975|261.0749999999998|268.0100000000002|283.0750000000007|283.21000000000004|286.9250000000029|290.9549999999999|294.21500000000015|301.1949999999997|316.375|316.9900000000016|317.3250000000007|319.7649999999994|327.375|353.59999999999945|353.880000000001|379.15500000000065|411.71000000000095__end_report__startTimestamp1448312527436__endTimestamp 13:02:07 INFO - 2015-11-23 13:02:07,441 DEBUG : BROWSER_OUTPUT: openingTimes=243.3050000000003,256.90499999999975,261.0749999999998,268.0100000000002,283.0750000000007,283.21000000000004,286.9250000000029,290.9549999999999,294.21500000000015,301.1949999999997,316.375,316.9900000000016,317.3250000000007,319.7649999999994,327.375,353.59999999999945,353.880000000001,379.15500000000065,411.71000000000095 13:02:07 INFO - 2015-11-23 13:02:07,441 DEBUG : BROWSER_OUTPUT: avgOpenTime:304.67 13:02:07 INFO - 2015-11-23 13:02:07,441 DEBUG : BROWSER_OUTPUT: minOpenTime:228.33 13:02:07 INFO - 2015-11-23 13:02:07,442 DEBUG : BROWSER_OUTPUT: maxOpenTime:411.71 13:02:07 INFO - 2015-11-23 13:02:07,442 DEBUG : BROWSER_OUTPUT: medOpenTime:297.7049999999999 13:02:07 INFO - 2015-11-23 13:02:07,442 DEBUG : BROWSER_OUTPUT: __xulWinOpenTime:297.7049999999999 13:02:08 INFO - 2015-11-23 13:02:08,489 INFO : Browser exited with error code: 0 13:02:08 INFO - 2015-11-23 13:02:08,503 INFO : Completed test tpaint (00:00:34) 13:02:08 INFO - 2015-11-23 13:02:08,503 INFO : Starting test sessionrestore 13:02:08 INFO - 2015-11-23 13:02:08,503 DEBUG : operating with platform_type : linux_ 13:02:08 INFO - 2015-11-23 13:02:08,503 INFO : Initialising browser for sessionrestore test... 13:02:08 INFO - 2015-11-23 13:02:08,513 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpwmMp9m/profile http://localhost:53751/getInfo.html 13:02:15 INFO - 2015-11-23 13:02:15,992 DEBUG : BROWSER_OUTPUT: __metrics Screen width/height:1600/1200 13:02:15 INFO - 2015-11-23 13:02:15,993 DEBUG : BROWSER_OUTPUT: colorDepth:24 13:02:15 INFO - 2015-11-23 13:02:15,993 DEBUG : BROWSER_OUTPUT: Browser inner width/height: 1151/811 13:02:15 INFO - 2015-11-23 13:02:15,993 DEBUG : BROWSER_OUTPUT: __metrics 13:02:16 ERROR - 2015-11-23 13:02:16,283 DEBUG : BROWSER_OUTPUT: JavaScript error: chrome://browser/content/browser.js, line 17078: TypeError: browser.permitUnload is not a function 13:02:16 ERROR - 2015-11-23 13:02:16,620 DEBUG : BROWSER_OUTPUT: JavaScript error: chrome://browser/content/browser.js, line 17078: TypeError: browser.permitUnload is not a function 13:02:17 INFO - 2015-11-23 13:02:17,641 INFO : Browser initialized. 13:02:17 INFO - 2015-11-23 13:02:17,642 INFO : Running cycle 1/10 for sessionrestore test... 13:02:17 INFO - 2015-11-23 13:02:17,642 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpwmMp9m/profile/sessionstore.js 13:02:17 INFO - 2015-11-23 13:02:17,644 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpwmMp9m/profile/sessionCheckpoints.json 13:02:17 INFO - 2015-11-23 13:02:17,645 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpwmMp9m/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:02:23 INFO - 2015-11-23 13:02:23,373 DEBUG : BROWSER_OUTPUT: __start_report1476__end_report 13:02:23 INFO - 2015-11-23 13:02:23,374 DEBUG : BROWSER_OUTPUT: 13:02:23 INFO - 2015-11-23 13:02:23,374 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312543373__endTimestamp 13:02:23 INFO - 2015-11-23 13:02:23,374 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,150 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,150 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,150 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,151 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,151 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,151 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,151 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,151 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,151 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,151 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,151 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,151 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,152 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,152 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,152 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,152 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,152 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,152 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,152 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,152 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,152 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,152 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,153 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,153 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,153 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,153 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,153 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,153 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,153 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,153 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,153 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,154 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,154 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,154 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,154 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,154 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,154 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,154 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,154 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,154 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,154 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,155 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,155 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,155 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,155 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,155 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,155 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,155 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,155 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,155 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,155 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,156 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,156 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:24 INFO - 2015-11-23 13:02:24,156 DEBUG : BROWSER_OUTPUT: 13:02:24 INFO - 2015-11-23 13:02:24,897 INFO : Browser exited with error code: 0 13:02:24 INFO - 2015-11-23 13:02:24,899 INFO : Running cycle 2/10 for sessionrestore test... 13:02:24 INFO - 2015-11-23 13:02:24,899 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpwmMp9m/profile/sessionstore.js 13:02:24 INFO - 2015-11-23 13:02:24,901 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpwmMp9m/profile/sessionCheckpoints.json 13:02:24 INFO - 2015-11-23 13:02:24,902 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpwmMp9m/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:02:29 INFO - 2015-11-23 13:02:29,858 DEBUG : BROWSER_OUTPUT: __start_report1171__end_report 13:02:29 INFO - 2015-11-23 13:02:29,858 DEBUG : BROWSER_OUTPUT: 13:02:29 INFO - 2015-11-23 13:02:29,858 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312549858__endTimestamp 13:02:29 INFO - 2015-11-23 13:02:29,858 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,586 DEBUG : BROWSER_OUTPUT: [Child 5715] WARNING: pipe error (3): Connection reset by peer: file /builds/slave/fx-team-l64-000000000000000000/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 459 13:02:30 INFO - 2015-11-23 13:02:30,586 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,586 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:30 INFO - 2015-11-23 13:02:30,586 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,587 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,587 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:30 INFO - 2015-11-23 13:02:30,587 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,587 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,587 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:30 INFO - 2015-11-23 13:02:30,587 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,587 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,588 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:30 INFO - 2015-11-23 13:02:30,588 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,588 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,588 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:30 INFO - 2015-11-23 13:02:30,588 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,588 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,589 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:30 INFO - 2015-11-23 13:02:30,589 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,589 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,589 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:30 INFO - 2015-11-23 13:02:30,589 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,589 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,589 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:30 INFO - 2015-11-23 13:02:30,589 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,589 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,590 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:30 INFO - 2015-11-23 13:02:30,590 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,590 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,590 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:30 INFO - 2015-11-23 13:02:30,590 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,590 DEBUG : BROWSER_OUTPUT: 13:02:30 INFO - 2015-11-23 13:02:30,590 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:30 INFO - 2015-11-23 13:02:30,590 DEBUG : BROWSER_OUTPUT: 13:02:31 INFO - 2015-11-23 13:02:31,285 INFO : Browser exited with error code: 0 13:02:31 INFO - 2015-11-23 13:02:31,287 INFO : Running cycle 3/10 for sessionrestore test... 13:02:31 INFO - 2015-11-23 13:02:31,287 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpwmMp9m/profile/sessionstore.js 13:02:31 INFO - 2015-11-23 13:02:31,289 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpwmMp9m/profile/sessionCheckpoints.json 13:02:31 INFO - 2015-11-23 13:02:31,290 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpwmMp9m/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:02:36 INFO - 2015-11-23 13:02:36,226 DEBUG : BROWSER_OUTPUT: __start_report1150__end_report 13:02:36 INFO - 2015-11-23 13:02:36,226 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,226 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312556224__endTimestamp 13:02:36 INFO - 2015-11-23 13:02:36,226 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,982 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,982 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:36 INFO - 2015-11-23 13:02:36,982 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,983 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,983 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:36 INFO - 2015-11-23 13:02:36,983 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,983 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,983 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:36 INFO - 2015-11-23 13:02:36,983 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,983 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,983 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:36 INFO - 2015-11-23 13:02:36,983 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,983 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:36 INFO - 2015-11-23 13:02:36,984 DEBUG : BROWSER_OUTPUT: 13:02:37 INFO - 2015-11-23 13:02:37,693 INFO : Browser exited with error code: 0 13:02:37 INFO - 2015-11-23 13:02:37,695 INFO : Running cycle 4/10 for sessionrestore test... 13:02:37 INFO - 2015-11-23 13:02:37,695 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpwmMp9m/profile/sessionstore.js 13:02:37 INFO - 2015-11-23 13:02:37,697 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpwmMp9m/profile/sessionCheckpoints.json 13:02:37 INFO - 2015-11-23 13:02:37,698 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpwmMp9m/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:02:42 INFO - 2015-11-23 13:02:42,744 DEBUG : BROWSER_OUTPUT: __start_report1169__end_report 13:02:42 INFO - 2015-11-23 13:02:42,744 DEBUG : BROWSER_OUTPUT: 13:02:42 INFO - 2015-11-23 13:02:42,744 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312562744__endTimestamp 13:02:42 INFO - 2015-11-23 13:02:42,745 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,505 DEBUG : BROWSER_OUTPUT: [Child 5955] WARNING: pipe error: Broken pipe: file /builds/slave/fx-team-l64-000000000000000000/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 760 13:02:43 INFO - 2015-11-23 13:02:43,506 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,506 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:43 INFO - 2015-11-23 13:02:43,506 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,506 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,506 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:43 INFO - 2015-11-23 13:02:43,506 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,506 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,506 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:43 INFO - 2015-11-23 13:02:43,506 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,506 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,506 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:43 INFO - 2015-11-23 13:02:43,507 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,507 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,507 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:43 INFO - 2015-11-23 13:02:43,507 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,507 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,507 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:43 INFO - 2015-11-23 13:02:43,507 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,507 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,507 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:43 INFO - 2015-11-23 13:02:43,507 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,507 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,508 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:43 INFO - 2015-11-23 13:02:43,508 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,508 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,508 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:43 INFO - 2015-11-23 13:02:43,508 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,508 DEBUG : BROWSER_OUTPUT: 13:02:43 INFO - 2015-11-23 13:02:43,508 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:43 INFO - 2015-11-23 13:02:43,508 DEBUG : BROWSER_OUTPUT: 13:02:44 INFO - 2015-11-23 13:02:44,337 INFO : Browser exited with error code: 0 13:02:44 INFO - 2015-11-23 13:02:44,339 INFO : Running cycle 5/10 for sessionrestore test... 13:02:44 INFO - 2015-11-23 13:02:44,339 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpwmMp9m/profile/sessionstore.js 13:02:44 INFO - 2015-11-23 13:02:44,341 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpwmMp9m/profile/sessionCheckpoints.json 13:02:44 INFO - 2015-11-23 13:02:44,342 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpwmMp9m/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:02:49 INFO - 2015-11-23 13:02:49,162 DEBUG : BROWSER_OUTPUT: __start_report1132__end_report 13:02:49 INFO - 2015-11-23 13:02:49,162 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,162 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312569161__endTimestamp 13:02:49 INFO - 2015-11-23 13:02:49,162 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,906 DEBUG : BROWSER_OUTPUT: [Child 6073] WARNING: pipe error (3): Connection reset by peer: file /builds/slave/fx-team-l64-000000000000000000/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 459 13:02:49 INFO - 2015-11-23 13:02:49,907 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,907 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,907 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,907 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,907 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,907 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,908 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,908 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,908 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,908 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,908 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,908 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,908 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,908 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,908 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,909 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,909 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,909 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,909 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,909 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,909 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,909 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,909 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,909 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,910 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,910 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,910 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,910 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,910 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,910 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,910 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,910 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,910 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,911 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,911 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,911 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,911 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,911 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,911 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,911 DEBUG : BROWSER_OUTPUT: 13:02:49 INFO - 2015-11-23 13:02:49,911 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:49 INFO - 2015-11-23 13:02:49,911 DEBUG : BROWSER_OUTPUT: 13:02:50 INFO - 2015-11-23 13:02:50,773 INFO : Browser exited with error code: 0 13:02:50 INFO - 2015-11-23 13:02:50,775 INFO : Running cycle 6/10 for sessionrestore test... 13:02:50 INFO - 2015-11-23 13:02:50,775 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpwmMp9m/profile/sessionstore.js 13:02:50 INFO - 2015-11-23 13:02:50,777 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpwmMp9m/profile/sessionCheckpoints.json 13:02:50 INFO - 2015-11-23 13:02:50,778 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpwmMp9m/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:02:55 INFO - 2015-11-23 13:02:55,815 DEBUG : BROWSER_OUTPUT: __start_report1152__end_report 13:02:55 INFO - 2015-11-23 13:02:55,815 DEBUG : BROWSER_OUTPUT: 13:02:55 INFO - 2015-11-23 13:02:55,815 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312575811__endTimestamp 13:02:55 INFO - 2015-11-23 13:02:55,815 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,543 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,543 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,543 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,543 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,543 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,543 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,543 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,543 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,543 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,543 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,544 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,544 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,544 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,544 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,544 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,544 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,544 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,544 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,544 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,544 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,545 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,545 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,545 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,545 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,545 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,545 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,546 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,546 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,546 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,546 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,546 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,546 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,546 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,547 DEBUG : BROWSER_OUTPUT: 13:02:56 INFO - 2015-11-23 13:02:56,547 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:02:56 INFO - 2015-11-23 13:02:56,547 DEBUG : BROWSER_OUTPUT: 13:02:57 INFO - 2015-11-23 13:02:57,341 INFO : Browser exited with error code: 0 13:02:57 INFO - 2015-11-23 13:02:57,343 INFO : Running cycle 7/10 for sessionrestore test... 13:02:57 INFO - 2015-11-23 13:02:57,343 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpwmMp9m/profile/sessionstore.js 13:02:57 INFO - 2015-11-23 13:02:57,345 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpwmMp9m/profile/sessionCheckpoints.json 13:02:57 INFO - 2015-11-23 13:02:57,346 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpwmMp9m/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:02 INFO - 2015-11-23 13:03:02,478 DEBUG : BROWSER_OUTPUT: __start_report1224__end_report 13:03:02 INFO - 2015-11-23 13:03:02,478 DEBUG : BROWSER_OUTPUT: 13:03:02 INFO - 2015-11-23 13:03:02,478 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312582477__endTimestamp 13:03:02 INFO - 2015-11-23 13:03:02,478 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,202 DEBUG : BROWSER_OUTPUT: [Child 6311] WARNING: pipe error: Broken pipe: file /builds/slave/fx-team-l64-000000000000000000/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 760 13:03:03 INFO - 2015-11-23 13:03:03,202 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,202 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,203 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,204 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:03 INFO - 2015-11-23 13:03:03,205 DEBUG : BROWSER_OUTPUT: 13:03:04 INFO - 2015-11-23 13:03:04,090 INFO : Browser exited with error code: 0 13:03:04 INFO - 2015-11-23 13:03:04,091 INFO : Running cycle 8/10 for sessionrestore test... 13:03:04 INFO - 2015-11-23 13:03:04,091 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpwmMp9m/profile/sessionstore.js 13:03:04 INFO - 2015-11-23 13:03:04,093 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpwmMp9m/profile/sessionCheckpoints.json 13:03:04 INFO - 2015-11-23 13:03:04,094 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpwmMp9m/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:09 INFO - 2015-11-23 13:03:09,176 DEBUG : BROWSER_OUTPUT: __start_report1165__end_report 13:03:09 INFO - 2015-11-23 13:03:09,176 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,177 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312589174__endTimestamp 13:03:09 INFO - 2015-11-23 13:03:09,177 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,937 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,937 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:09 INFO - 2015-11-23 13:03:09,937 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,937 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,937 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,938 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:09 INFO - 2015-11-23 13:03:09,939 DEBUG : BROWSER_OUTPUT: 13:03:10 INFO - 2015-11-23 13:03:10,769 INFO : Browser exited with error code: 0 13:03:10 INFO - 2015-11-23 13:03:10,771 INFO : Running cycle 9/10 for sessionrestore test... 13:03:10 INFO - 2015-11-23 13:03:10,771 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpwmMp9m/profile/sessionstore.js 13:03:10 INFO - 2015-11-23 13:03:10,773 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpwmMp9m/profile/sessionCheckpoints.json 13:03:10 INFO - 2015-11-23 13:03:10,774 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpwmMp9m/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:15 INFO - 2015-11-23 13:03:15,709 DEBUG : BROWSER_OUTPUT: __start_report1156__end_report 13:03:15 INFO - 2015-11-23 13:03:15,709 DEBUG : BROWSER_OUTPUT: 13:03:15 INFO - 2015-11-23 13:03:15,709 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312595707__endTimestamp 13:03:15 INFO - 2015-11-23 13:03:15,709 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,434 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,434 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:16 INFO - 2015-11-23 13:03:16,435 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,436 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,436 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:16 INFO - 2015-11-23 13:03:16,436 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,436 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,436 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:16 INFO - 2015-11-23 13:03:16,436 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,436 DEBUG : BROWSER_OUTPUT: 13:03:16 INFO - 2015-11-23 13:03:16,436 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:16 INFO - 2015-11-23 13:03:16,436 DEBUG : BROWSER_OUTPUT: 13:03:17 INFO - 2015-11-23 13:03:17,313 INFO : Browser exited with error code: 0 13:03:17 INFO - 2015-11-23 13:03:17,315 INFO : Running cycle 10/10 for sessionrestore test... 13:03:17 INFO - 2015-11-23 13:03:17,315 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpwmMp9m/profile/sessionstore.js 13:03:17 INFO - 2015-11-23 13:03:17,317 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpwmMp9m/profile/sessionCheckpoints.json 13:03:17 INFO - 2015-11-23 13:03:17,318 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpwmMp9m/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:22 INFO - 2015-11-23 13:03:22,321 DEBUG : BROWSER_OUTPUT: __start_report1173__end_report 13:03:22 INFO - 2015-11-23 13:03:22,321 DEBUG : BROWSER_OUTPUT: 13:03:22 INFO - 2015-11-23 13:03:22,321 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312602316__endTimestamp 13:03:22 INFO - 2015-11-23 13:03:22,321 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,017 DEBUG : BROWSER_OUTPUT: [Child 6667] WARNING: pipe error (3): Connection reset by peer: file /builds/slave/fx-team-l64-000000000000000000/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 459 13:03:23 INFO - 2015-11-23 13:03:23,017 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,017 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,017 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,017 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,017 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,017 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,018 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,018 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,018 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,018 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,018 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,018 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,018 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,018 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,018 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,018 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,019 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,019 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,019 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,019 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,019 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,019 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,019 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,019 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,019 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,019 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,020 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,020 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,020 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,020 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,020 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,020 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,020 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,020 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,020 DEBUG : BROWSER_OUTPUT: ###!!! [Child][MessageChannel] Error: (msgtype=0x280043,name=PBrowser::Msg___delete__) Channel closing: too late to send/recv, messages will be lost 13:03:23 INFO - 2015-11-23 13:03:23,020 DEBUG : BROWSER_OUTPUT: 13:03:23 INFO - 2015-11-23 13:03:23,865 INFO : Browser exited with error code: 0 13:03:23 INFO - 2015-11-23 13:03:23,879 INFO : Completed test sessionrestore (00:01:15) 13:03:23 INFO - 2015-11-23 13:03:23,879 INFO : Starting test sessionrestore_no_auto_restore 13:03:23 INFO - 2015-11-23 13:03:23,879 DEBUG : operating with platform_type : linux_ 13:03:23 INFO - 2015-11-23 13:03:23,880 INFO : Initialising browser for sessionrestore_no_auto_restore test... 13:03:23 INFO - 2015-11-23 13:03:23,888 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpnltrUj/profile http://localhost:53751/getInfo.html 13:03:27 INFO - 2015-11-23 13:03:27,833 DEBUG : BROWSER_OUTPUT: __metrics Screen width/height:1600/1200 13:03:27 INFO - 2015-11-23 13:03:27,833 DEBUG : BROWSER_OUTPUT: colorDepth:24 13:03:27 INFO - 2015-11-23 13:03:27,833 DEBUG : BROWSER_OUTPUT: Browser inner width/height: 1151/811 13:03:27 INFO - 2015-11-23 13:03:27,833 DEBUG : BROWSER_OUTPUT: __metrics 13:03:28 INFO - 2015-11-23 13:03:28,981 INFO : Browser initialized. 13:03:28 INFO - 2015-11-23 13:03:28,982 INFO : Running cycle 1/10 for sessionrestore_no_auto_restore test... 13:03:28 INFO - 2015-11-23 13:03:28,982 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpnltrUj/profile/sessionstore.js 13:03:28 INFO - 2015-11-23 13:03:28,984 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpnltrUj/profile/sessionCheckpoints.json 13:03:28 INFO - 2015-11-23 13:03:28,985 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpnltrUj/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:31 INFO - 2015-11-23 13:03:31,168 DEBUG : BROWSER_OUTPUT: __start_report1166__end_report 13:03:31 INFO - 2015-11-23 13:03:31,169 DEBUG : BROWSER_OUTPUT: 13:03:31 INFO - 2015-11-23 13:03:31,169 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312611165__endTimestamp 13:03:31 INFO - 2015-11-23 13:03:31,169 DEBUG : BROWSER_OUTPUT: 13:03:32 INFO - 2015-11-23 13:03:32,181 INFO : Browser exited with error code: 0 13:03:32 INFO - 2015-11-23 13:03:32,183 INFO : Running cycle 2/10 for sessionrestore_no_auto_restore test... 13:03:32 INFO - 2015-11-23 13:03:32,183 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpnltrUj/profile/sessionstore.js 13:03:32 INFO - 2015-11-23 13:03:32,185 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpnltrUj/profile/sessionCheckpoints.json 13:03:32 INFO - 2015-11-23 13:03:32,186 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpnltrUj/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:33 INFO - 2015-11-23 13:03:33,740 DEBUG : BROWSER_OUTPUT: __start_report741__end_report 13:03:33 INFO - 2015-11-23 13:03:33,740 DEBUG : BROWSER_OUTPUT: 13:03:33 INFO - 2015-11-23 13:03:33,740 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312613733__endTimestamp 13:03:33 INFO - 2015-11-23 13:03:33,740 DEBUG : BROWSER_OUTPUT: 13:03:34 INFO - 2015-11-23 13:03:34,609 INFO : Browser exited with error code: 0 13:03:34 INFO - 2015-11-23 13:03:34,611 INFO : Running cycle 3/10 for sessionrestore_no_auto_restore test... 13:03:34 INFO - 2015-11-23 13:03:34,611 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpnltrUj/profile/sessionstore.js 13:03:34 INFO - 2015-11-23 13:03:34,613 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpnltrUj/profile/sessionCheckpoints.json 13:03:34 INFO - 2015-11-23 13:03:34,614 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpnltrUj/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:36 INFO - 2015-11-23 13:03:36,177 DEBUG : BROWSER_OUTPUT: __start_report747__end_report 13:03:36 INFO - 2015-11-23 13:03:36,177 DEBUG : BROWSER_OUTPUT: 13:03:36 INFO - 2015-11-23 13:03:36,177 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312616175__endTimestamp 13:03:36 INFO - 2015-11-23 13:03:36,177 DEBUG : BROWSER_OUTPUT: 13:03:37 INFO - 2015-11-23 13:03:37,149 INFO : Browser exited with error code: 0 13:03:37 INFO - 2015-11-23 13:03:37,151 INFO : Running cycle 4/10 for sessionrestore_no_auto_restore test... 13:03:37 INFO - 2015-11-23 13:03:37,151 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpnltrUj/profile/sessionstore.js 13:03:37 INFO - 2015-11-23 13:03:37,153 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpnltrUj/profile/sessionCheckpoints.json 13:03:37 INFO - 2015-11-23 13:03:37,154 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpnltrUj/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:38 INFO - 2015-11-23 13:03:38,753 DEBUG : BROWSER_OUTPUT: __start_report750__end_report 13:03:38 INFO - 2015-11-23 13:03:38,754 DEBUG : BROWSER_OUTPUT: 13:03:38 INFO - 2015-11-23 13:03:38,754 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312618753__endTimestamp 13:03:38 INFO - 2015-11-23 13:03:38,754 DEBUG : BROWSER_OUTPUT: 13:03:39 INFO - 2015-11-23 13:03:39,757 INFO : Browser exited with error code: 0 13:03:39 INFO - 2015-11-23 13:03:39,759 INFO : Running cycle 5/10 for sessionrestore_no_auto_restore test... 13:03:39 INFO - 2015-11-23 13:03:39,759 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpnltrUj/profile/sessionstore.js 13:03:39 INFO - 2015-11-23 13:03:39,761 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpnltrUj/profile/sessionCheckpoints.json 13:03:39 INFO - 2015-11-23 13:03:39,761 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpnltrUj/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:41 INFO - 2015-11-23 13:03:41,341 DEBUG : BROWSER_OUTPUT: __start_report743__end_report 13:03:41 INFO - 2015-11-23 13:03:41,342 DEBUG : BROWSER_OUTPUT: 13:03:41 INFO - 2015-11-23 13:03:41,342 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312621338__endTimestamp 13:03:41 INFO - 2015-11-23 13:03:41,342 DEBUG : BROWSER_OUTPUT: 13:03:42 INFO - 2015-11-23 13:03:42,381 INFO : Browser exited with error code: 0 13:03:42 INFO - 2015-11-23 13:03:42,383 INFO : Running cycle 6/10 for sessionrestore_no_auto_restore test... 13:03:42 INFO - 2015-11-23 13:03:42,383 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpnltrUj/profile/sessionstore.js 13:03:42 INFO - 2015-11-23 13:03:42,385 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpnltrUj/profile/sessionCheckpoints.json 13:03:42 INFO - 2015-11-23 13:03:42,386 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpnltrUj/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:43 INFO - 2015-11-23 13:03:43,943 DEBUG : BROWSER_OUTPUT: __start_report742__end_report 13:03:43 INFO - 2015-11-23 13:03:43,943 DEBUG : BROWSER_OUTPUT: 13:03:43 INFO - 2015-11-23 13:03:43,943 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312623943__endTimestamp 13:03:43 INFO - 2015-11-23 13:03:43,944 DEBUG : BROWSER_OUTPUT: 13:03:44 INFO - 2015-11-23 13:03:44,957 INFO : Browser exited with error code: 0 13:03:44 INFO - 2015-11-23 13:03:44,959 INFO : Running cycle 7/10 for sessionrestore_no_auto_restore test... 13:03:44 INFO - 2015-11-23 13:03:44,959 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpnltrUj/profile/sessionstore.js 13:03:44 INFO - 2015-11-23 13:03:44,961 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpnltrUj/profile/sessionCheckpoints.json 13:03:44 INFO - 2015-11-23 13:03:44,962 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpnltrUj/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:46 INFO - 2015-11-23 13:03:46,547 DEBUG : BROWSER_OUTPUT: __start_report744__end_report 13:03:46 INFO - 2015-11-23 13:03:46,547 DEBUG : BROWSER_OUTPUT: 13:03:46 INFO - 2015-11-23 13:03:46,547 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312626547__endTimestamp 13:03:46 INFO - 2015-11-23 13:03:46,548 DEBUG : BROWSER_OUTPUT: 13:03:47 INFO - 2015-11-23 13:03:47,569 INFO : Browser exited with error code: 0 13:03:47 INFO - 2015-11-23 13:03:47,571 INFO : Running cycle 8/10 for sessionrestore_no_auto_restore test... 13:03:47 INFO - 2015-11-23 13:03:47,571 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpnltrUj/profile/sessionstore.js 13:03:47 INFO - 2015-11-23 13:03:47,573 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpnltrUj/profile/sessionCheckpoints.json 13:03:47 INFO - 2015-11-23 13:03:47,574 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpnltrUj/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:49 INFO - 2015-11-23 13:03:49,155 DEBUG : BROWSER_OUTPUT: __start_report745__end_report 13:03:49 INFO - 2015-11-23 13:03:49,156 DEBUG : BROWSER_OUTPUT: 13:03:49 INFO - 2015-11-23 13:03:49,156 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312629155__endTimestamp 13:03:49 INFO - 2015-11-23 13:03:49,156 DEBUG : BROWSER_OUTPUT: 13:03:50 INFO - 2015-11-23 13:03:50,209 INFO : Browser exited with error code: 0 13:03:50 INFO - 2015-11-23 13:03:50,211 INFO : Running cycle 9/10 for sessionrestore_no_auto_restore test... 13:03:50 INFO - 2015-11-23 13:03:50,211 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpnltrUj/profile/sessionstore.js 13:03:50 INFO - 2015-11-23 13:03:50,213 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpnltrUj/profile/sessionCheckpoints.json 13:03:50 INFO - 2015-11-23 13:03:50,214 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpnltrUj/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:51 INFO - 2015-11-23 13:03:51,849 DEBUG : BROWSER_OUTPUT: __start_report782__end_report 13:03:51 INFO - 2015-11-23 13:03:51,849 DEBUG : BROWSER_OUTPUT: 13:03:51 INFO - 2015-11-23 13:03:51,849 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312631844__endTimestamp 13:03:51 INFO - 2015-11-23 13:03:51,849 DEBUG : BROWSER_OUTPUT: 13:03:52 INFO - 2015-11-23 13:03:52,941 INFO : Browser exited with error code: 0 13:03:52 INFO - 2015-11-23 13:03:52,943 INFO : Running cycle 10/10 for sessionrestore_no_auto_restore test... 13:03:52 INFO - 2015-11-23 13:03:52,943 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /tmp/tmpnltrUj/profile/sessionstore.js 13:03:52 INFO - 2015-11-23 13:03:52,945 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /tmp/tmpnltrUj/profile/sessionCheckpoints.json 13:03:52 INFO - 2015-11-23 13:03:52,946 DEBUG : command line: /builds/slave/test/build/application/firefox/firefox -profile /tmp/tmpnltrUj/profile http://localhost:53751/startup_test/sessionrestore/index.html 13:03:54 INFO - 2015-11-23 13:03:54,549 DEBUG : BROWSER_OUTPUT: __start_report744__end_report 13:03:54 INFO - 2015-11-23 13:03:54,549 DEBUG : BROWSER_OUTPUT: 13:03:54 INFO - 2015-11-23 13:03:54,549 DEBUG : BROWSER_OUTPUT: __startTimestamp1448312634547__endTimestamp 13:03:54 INFO - 2015-11-23 13:03:54,549 DEBUG : BROWSER_OUTPUT: 13:03:55 INFO - 2015-11-23 13:03:55,617 INFO : Browser exited with error code: 0 13:03:55 INFO - 2015-11-23 13:03:55,630 INFO : Completed test sessionrestore_no_auto_restore (00:00:31) 13:03:55 INFO - 2015-11-23 13:03:55,965 INFO : Completed test suite (00:05:08) 13:03:55 INFO - 2015-11-23 13:03:55,965 DEBUG : Working with test: a11yr 13:03:55 INFO - 2015-11-23 13:03:55,965 DEBUG : Generating results file: a11yr 13:03:55 INFO - 2015-11-23 13:03:55,965 DEBUG : Working with test: ts_paint 13:03:55 INFO - 2015-11-23 13:03:55,966 DEBUG : Generating results file: ts_paint 13:03:55 INFO - 2015-11-23 13:03:55,966 DEBUG : Working with test: tpaint 13:03:55 INFO - 2015-11-23 13:03:55,966 DEBUG : Generating results file: tpaint 13:03:55 INFO - 2015-11-23 13:03:55,967 DEBUG : Working with test: sessionrestore 13:03:55 INFO - 2015-11-23 13:03:55,967 DEBUG : Generating results file: sessionrestore 13:03:55 INFO - 2015-11-23 13:03:55,967 DEBUG : Working with test: sessionrestore_no_auto_restore 13:03:55 INFO - 2015-11-23 13:03:55,967 DEBUG : Generating results file: sessionrestore_no_auto_restore 13:03:55 INFO - 2015-11-23 13:03:55,968 INFO : Posting result 0 of 5 to http://graphs.mozilla.org/server/collect.cgi, attempt 0 13:03:56 INFO - 2015-11-23 13:03:56,017 DEBUG : process_Request line: a11yr_paint graph.html#tests=[[223,132,43]] 13:03:56 INFO - 2015-11-23 13:03:56,017 DEBUG : process_Request line: a11yr_paint 709.15 graph.html#tests=[[223,132,43]] 13:03:56 INFO - 2015-11-23 13:03:56,017 INFO : Posting result 1 of 5 to http://graphs.mozilla.org/server/collect.cgi, attempt 0 13:03:56 INFO - 2015-11-23 13:03:56,084 DEBUG : process_Request line: ts_paint graph.html#tests=[[83,132,43]] 13:03:56 INFO - 2015-11-23 13:03:56,084 DEBUG : process_Request line: ts_paint 528.16 graph.html#tests=[[83,132,43]] 13:03:56 INFO - 2015-11-23 13:03:56,084 INFO : Posting result 2 of 5 to http://graphs.mozilla.org/server/collect.cgi, attempt 0 13:03:56 INFO - 2015-11-23 13:03:56,123 DEBUG : process_Request line: tpaint graph.html#tests=[[82,132,43]] 13:03:56 INFO - 2015-11-23 13:03:56,123 DEBUG : process_Request line: tpaint 316.99 graph.html#tests=[[82,132,43]] 13:03:56 INFO - 2015-11-23 13:03:56,123 INFO : Posting result 3 of 5 to http://graphs.mozilla.org/server/collect.cgi, attempt 0 13:03:56 INFO - 2015-11-23 13:03:56,179 DEBUG : process_Request line: sessionrestore graph.html#tests=[[313,132,43]] 13:03:56 INFO - 2015-11-23 13:03:56,179 DEBUG : process_Request line: sessionrestore 1193.39 graph.html#tests=[[313,132,43]] 13:03:56 INFO - 2015-11-23 13:03:56,179 INFO : Posting result 4 of 5 to http://graphs.mozilla.org/server/collect.cgi, attempt 0 13:03:56 INFO - 2015-11-23 13:03:56,246 DEBUG : process_Request line: sessionrestore_no_auto_restore graph.html#tests=[[315,132,43]] 13:03:56 INFO - 2015-11-23 13:03:56,246 DEBUG : process_Request line: sessionrestore_no_auto_restore 782.50 graph.html#tests=[[315,132,43]] 13:03:56 INFO - 2015-11-23 13:03:56,247 INFO : PERFHERDER_DATA: {"framework": {"name": "talos"}, "suites": [{"lowerIsBetter": true, "subtests": [{"lowerIsBetter": true, "replicates": [1243.0, 1294.0, 1291.0, 1294.0, 1312.0, 1308.0, 1317.0, 1306.0, 1299.0, 1307.0, 1309.0, 1302.0, 1302.0, 1312.0, 1310.0, 1301.0, 1298.0, 1305.0, 1303.0, 1306.0, 1524.0, 1301.0, 1305.0, 1319.0, 1550.0], "unit": "ms", "name": "dhtml.html", "value": 1305.5}, {"lowerIsBetter": true, "replicates": [379.0, 382.0, 395.0, 386.0, 388.0, 394.0, 383.0, 384.0, 374.0, 385.0, 380.0, 393.0, 388.0, 385.0, 376.0, 385.0, 391.0, 379.0, 393.0, 376.0, 381.0, 386.0, 387.0, 387.0, 384.0], "unit": "ms", "name": "tablemutation.html", "value": 385.0}], "name": "a11yr", "value": 709.1471678462153}, {"subtests": [{"replicates": [499.0, 538.0, 572.0, 587.0, 498.0, 562.0, 537.0, 494.0, 535.0, 540.0, 498.0, 496.0, 504.0, 519.0, 547.0, 538.0, 537.0, 543.0, 528.0, 504.0], "name": "ts_paint", "value": 537.0}], "name": "ts_paint", "value": 537.0}, {"subtests": [{"replicates": [228.32500000000073, 243.3050000000003, 256.90499999999975, 261.0749999999998, 268.0100000000002, 283.0750000000007, 283.21000000000004, 286.9250000000029, 290.9549999999999, 294.21500000000015, 301.1949999999997, 316.375, 316.9900000000016, 317.3250000000007, 319.7649999999994, 327.375, 353.59999999999945, 353.880000000001, 379.15500000000065, 411.71000000000095], "name": "tpaint", "value": 316.9900000000016}], "name": "tpaint", "value": 316.9900000000016}, {"subtests": [{"replicates": [1476.0, 1171.0, 1150.0, 1169.0, 1132.0, 1152.0, 1224.0, 1165.0, 1156.0, 1173.0], "name": "sessionrestore", "value": 1165.0}], "name": "sessionrestore", "value": 1165.0}, {"subtests": [{"replicates": [1166.0, 741.0, 747.0, 750.0, 743.0, 742.0, 744.0, 745.0, 782.0, 744.0], "name": "sessionrestore_no_auto_restore", "value": 744.0}], "name": "sessionrestore_no_auto_restore", "value": 744.0}]} 13:03:56 INFO - RETURN: a11yr_paint: 709.15 13:03:56 INFO - RETURN: ts_paint: 528.16 13:03:56 INFO - RETURN: tpaint: 316.99 13:03:56 INFO - RETURN: sessionrestore: 1193.39 13:03:56 INFO - RETURN: sessionrestore_no_auto_restore: 782.50 13:03:56 INFO - TinderboxPrint: TalosResult: {"graphserver": {"sessionrestore": {"url": "http://graphs.mozilla.org/graph.html#tests=[[313,132,43]]", "result": "1193.39"}, "a11yr_paint": {"url": "http://graphs.mozilla.org/graph.html#tests=[[223,132,43]]", "result": "709.15"}, "tpaint": {"url": "http://graphs.mozilla.org/graph.html#tests=[[82,132,43]]", "result": "316.99"}, "ts_paint": {"url": "http://graphs.mozilla.org/graph.html#tests=[[83,132,43]]", "result": "528.16"}, "sessionrestore_no_auto_restore": {"url": "http://graphs.mozilla.org/graph.html#tests=[[315,132,43]]", "result": "782.50"}}} 13:03:56 INFO - Return code: 0 13:03:56 ERROR - # TBPL SUCCESS # 13:03:56 INFO - Running post-action listener: _resource_record_post_action 13:03:56 INFO - Running post-run listener: _resource_record_post_run 13:03:57 INFO - Total resource usage - Wall time: 323s; CPU: 15.0%; Read bytes: 20480; Write bytes: 582303744; Read time: 28; Write time: 409780 13:03:57 INFO - install - Wall time: 14s; CPU: 14.0%; Read bytes: 0; Write bytes: 233480192; Read time: 0; Write time: 271216 13:03:57 INFO - run-tests - Wall time: 309s; CPU: 16.0%; Read bytes: 20480; Write bytes: 348823552; Read time: 28; Write time: 138564 13:03:57 INFO - Running post-run listener: _upload_blobber_files 13:03:57 INFO - Blob upload gear active. 13:03:57 INFO - There are no files to upload in the directory. Skipping the blob upload mechanism ... 13:03:57 INFO - Copying logs to upload dir... 13:03:57 INFO - mkdir: /builds/slave/test/build/upload/logs program finished with exit code 0 elapsedTime=351.615704 ========= master_lag: 0.03 ========= ========= Finished '/tools/buildbot/bin/python scripts/scripts/talos_script.py ...' (results: 0, elapsed: 5 mins, 51 secs) (at 2015-11-23 13:03:57.241197) ========= ========= Started set props: build_url (results: 0, elapsed: 0 secs) (at 2015-11-23 13:03:57.244850) ========= bash -c 'for file in `ls -1`; do cat $file; done' in dir /builds/slave/test/properties (timeout 1200 secs) watching logfiles {} argv: ['bash', '-c', 'for file in `ls -1`; do cat $file; done'] environment: DISPLAY=:0 HOME=/home/cltbld LANG=en_US.UTF-8 LANGUAGE=en_US:en LOGNAME=cltbld MAIL=/var/mail/cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript NO_EM_RESTART=1 PATH=/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games PWD=/builds/slave/test/properties SHELL=/bin/bash SHLVL=1 TERM=linux TMOUT=86400 USER=cltbld XDG_SESSION_COOKIE=919420d7ee4ef147bef0346300000385-1448312283.868710-972446830 XPCOM_DEBUG_BREAK=warn _=/tools/buildbot/bin/python using PTY: False build_url:https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2 program finished with exit code 0 elapsedTime=0.009911 build_url: 'https://queue.taskcluster.net/v1/task/WsFfSGx8Qu2guP2wehmoyw/artifacts/public/build/firefox-45.0a1.en-US.linux-x86_64.tar.bz2' ========= master_lag: 0.04 ========= ========= Finished set props: build_url (results: 0, elapsed: 0 secs) (at 2015-11-23 13:03:57.296261) ========= ========= Started 'rm -f ...' (results: 0, elapsed: 0 secs) (at 2015-11-23 13:03:57.296595) ========= rm -f oauth.txt in dir /builds/slave/test/. (timeout 1200 secs) watching logfiles {} argv: ['rm', '-f', 'oauth.txt'] environment: DISPLAY=:0 HOME=/home/cltbld LANG=en_US.UTF-8 LANGUAGE=en_US:en LOGNAME=cltbld MAIL=/var/mail/cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript NO_EM_RESTART=1 PATH=/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games PWD=/builds/slave/test SHELL=/bin/bash SHLVL=1 TERM=linux TMOUT=86400 USER=cltbld XDG_SESSION_COOKIE=919420d7ee4ef147bef0346300000385-1448312283.868710-972446830 XPCOM_DEBUG_BREAK=warn _=/tools/buildbot/bin/python using PTY: False program finished with exit code 0 elapsedTime=0.004494 ========= master_lag: 0.05 ========= ========= Finished 'rm -f ...' (results: 0, elapsed: 0 secs) (at 2015-11-23 13:03:57.346216) ========= ========= Started reboot skipped (results: 3, elapsed: 0 secs) (at 2015-11-23 13:03:57.346524) ========= ========= Finished reboot skipped (results: 3, elapsed: 0 secs) (at 2015-11-23 13:03:57.346802) ========= ========= Total master_lag: 0.24 =========