builder: fx-team_yosemite_test-other slave: t-yosemite-r5-0016 starttime: 1445634055.2 results: success (0) buildid: 20151023121232 builduid: 70c1a8410c6f4d2891f361e5be11844c revision: ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc ========= Started set props: master (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.200830) ========= master: http://buildbot-master107.bb.releng.scl3.mozilla.com:8201/ ========= Finished set props: master (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.201373) ========= ========= Started set props: basedir (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.201725) ========= bash -c pwd in dir /builds/slave/test/. (timeout 1200 secs) watching logfiles {} argv: ['bash', '-c', 'pwd'] environment: Apple_PubSub_Socket_Render=/private/tmp/com.apple.launchd.hzmkYpjbIV/Render GIT_SHARE_BASE_DIR=/builds/git-shared HG_SHARE_BASE_DIR=/builds/hg-shared HOME=/Users/cltbld IDLEIZER_DISABLE_SHUTDOWN=true LOGNAME=cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NO_EM_RESTART=1 PAGER=/bin/cat PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11 PWD=/builds/slave/test RUNNER_CONFIG_CMD=/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg SHELL=/bin/bash SSH_AUTH_SOCK=/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners TMPDIR=/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/ TWISTD_LOG_PATH=/builds/slave/twistd.log USER=cltbld VERSIONER_PYTHON_PREFER_32_BIT=no VERSIONER_PYTHON_VERSION=2.7 XPCOM_DEBUG_BREAK=warn XPC_FLAGS=0x0 XPC_SERVICE_NAME=0 __CF_USER_TEXT_ENCODING=0x1C:0x0:0x0 using PTY: False /builds/slave/test program finished with exit code 0 elapsedTime=0.005937 basedir: '/builds/slave/test' ========= Finished set props: basedir (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.290727) ========= ========= Started downloading to buildprops.json (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.291067) ========= ========= Finished downloading to buildprops.json (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.317847) ========= ========= Started 'rm -rf ...' (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.318337) ========= rm -rf properties in dir /builds/slave/test/. (timeout 1200 secs) watching logfiles {} argv: ['rm', '-rf', 'properties'] environment: Apple_PubSub_Socket_Render=/private/tmp/com.apple.launchd.hzmkYpjbIV/Render GIT_SHARE_BASE_DIR=/builds/git-shared HG_SHARE_BASE_DIR=/builds/hg-shared HOME=/Users/cltbld IDLEIZER_DISABLE_SHUTDOWN=true LOGNAME=cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NO_EM_RESTART=1 PAGER=/bin/cat PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11 PWD=/builds/slave/test RUNNER_CONFIG_CMD=/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg SHELL=/bin/bash SSH_AUTH_SOCK=/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners TMPDIR=/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/ TWISTD_LOG_PATH=/builds/slave/twistd.log USER=cltbld VERSIONER_PYTHON_PREFER_32_BIT=no VERSIONER_PYTHON_VERSION=2.7 XPCOM_DEBUG_BREAK=warn XPC_FLAGS=0x0 XPC_SERVICE_NAME=0 __CF_USER_TEXT_ENCODING=0x1C:0x0:0x0 using PTY: False program finished with exit code 0 elapsedTime=0.017623 ========= Finished 'rm -rf ...' (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.367742) ========= ========= Started set props: script_repo_url (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.368103) ========= script_repo_url: https://hg.mozilla.org/build/mozharness ========= Finished set props: script_repo_url (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.368542) ========= ========= Started 'bash -c ...' (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.368858) ========= 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: Apple_PubSub_Socket_Render=/private/tmp/com.apple.launchd.hzmkYpjbIV/Render GIT_SHARE_BASE_DIR=/builds/git-shared HG_SHARE_BASE_DIR=/builds/hg-shared HOME=/Users/cltbld IDLEIZER_DISABLE_SHUTDOWN=true LOGNAME=cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NO_EM_RESTART=1 PAGER=/bin/cat PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11 PWD=/builds/slave/test RUNNER_CONFIG_CMD=/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg SHELL=/bin/bash SSH_AUTH_SOCK=/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners TMPDIR=/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/ TWISTD_LOG_PATH=/builds/slave/twistd.log USER=cltbld VERSIONER_PYTHON_PREFER_32_BIT=no VERSIONER_PYTHON_VERSION=2.7 XPCOM_DEBUG_BREAK=warn XPC_FLAGS=0x0 XPC_SERVICE_NAME=0 __CF_USER_TEXT_ENCODING=0x1C:0x0:0x0 using PTY: False --2015-10-23 14:00:55-- https://hg.mozilla.org/build/tools/raw-file/default/buildfarm/utils/archiver_client.py Resolving hg.mozilla.org... 63.245.215.25, 63.245.215.102 Connecting to 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.86M=0.001s 2015-10-23 14:00:55 (8.86 MB/s) - `archiver_client.py' saved [12141/12141] program finished with exit code 0 elapsedTime=0.131940 ========= Finished 'bash -c ...' (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.516702) ========= ========= Started 'rm -rf ...' (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.517093) ========= rm -rf scripts in dir /builds/slave/test/. (timeout 1200 secs) watching logfiles {} argv: ['rm', '-rf', 'scripts'] environment: Apple_PubSub_Socket_Render=/private/tmp/com.apple.launchd.hzmkYpjbIV/Render GIT_SHARE_BASE_DIR=/builds/git-shared HG_SHARE_BASE_DIR=/builds/hg-shared HOME=/Users/cltbld IDLEIZER_DISABLE_SHUTDOWN=true LOGNAME=cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NO_EM_RESTART=1 PAGER=/bin/cat PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11 PWD=/builds/slave/test RUNNER_CONFIG_CMD=/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg SHELL=/bin/bash SSH_AUTH_SOCK=/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners TMPDIR=/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/ TWISTD_LOG_PATH=/builds/slave/twistd.log USER=cltbld VERSIONER_PYTHON_PREFER_32_BIT=no VERSIONER_PYTHON_VERSION=2.7 XPCOM_DEBUG_BREAK=warn XPC_FLAGS=0x0 XPC_SERVICE_NAME=0 __CF_USER_TEXT_ENCODING=0x1C:0x0:0x0 using PTY: False program finished with exit code 0 elapsedTime=0.074919 ========= Finished 'rm -rf ...' (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.607349) ========= ========= Started 'bash -c ...' (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:55.607815) ========= bash -c 'python archiver_client.py mozharness --repo integration/fx-team --rev ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc --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 ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc --destination scripts --debug'] environment: Apple_PubSub_Socket_Render=/private/tmp/com.apple.launchd.hzmkYpjbIV/Render GIT_SHARE_BASE_DIR=/builds/git-shared HG_SHARE_BASE_DIR=/builds/hg-shared HOME=/Users/cltbld IDLEIZER_DISABLE_SHUTDOWN=true LOGNAME=cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NO_EM_RESTART=1 PAGER=/bin/cat PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11 PWD=/builds/slave/test RUNNER_CONFIG_CMD=/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg SHELL=/bin/bash SSH_AUTH_SOCK=/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners TMPDIR=/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/ TWISTD_LOG_PATH=/builds/slave/twistd.log USER=cltbld VERSIONER_PYTHON_PREFER_32_BIT=no VERSIONER_PYTHON_VERSION=2.7 XPCOM_DEBUG_BREAK=warn XPC_FLAGS=0x0 XPC_SERVICE_NAME=0 __CF_USER_TEXT_ENCODING=0x1C:0x0:0x0 using PTY: False 2015-10-23 14:00:55,689 truncating revision to first 12 chars 2015-10-23 14:00:55,689 Setting DEBUG logging. 2015-10-23 14:00:55,689 attempt 1/10 2015-10-23 14:00:55,689 Getting archive location from https://api.pub.build.mozilla.org/archiver/hgmo/integration/fx-team/ccb7bb578fb1?&preferred_region=us-west-2&suffix=tar.gz&subdir=testing/mozharness 2015-10-23 14:00:56,275 unpacking tar archive at: fx-team-ccb7bb578fb1/testing/mozharness/ program finished with exit code 0 elapsedTime=0.839635 ========= Finished 'bash -c ...' (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:56.464279) ========= ========= Started downloading to oauth.txt (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:56.464676) ========= ========= Finished downloading to oauth.txt (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:56.477421) ========= ========= Started tinderboxprint_script_revlink (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:56.477793) ========= TinderboxPrint: script_revlink: https://hg.mozilla.org/build/mozharness/rev/production ========= Finished tinderboxprint_script_revlink (results: 0, elapsed: 0 secs) (at 2015-10-23 14:00:56.478268) ========= ========= Started '/tools/buildbot/bin/python scripts/scripts/talos_script.py ...' (results: 0, elapsed: 6 mins, 49 secs) (at 2015-10-23 14:00:56.478599) ========= /tools/buildbot/bin/python scripts/scripts/talos_script.py --suite other --add-option --webServer,localhost --branch-name Fx-Team --system-bits 64 --cfg talos/mac_config.py --download-symbols ondemand --use-talos-json --blob-upload-branch Fx-Team 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', '--add-option', '--webServer,localhost', '--branch-name', 'Fx-Team', '--system-bits', '64', '--cfg', 'talos/mac_config.py', '--download-symbols', 'ondemand', '--use-talos-json', '--blob-upload-branch', 'Fx-Team'] environment: Apple_PubSub_Socket_Render=/private/tmp/com.apple.launchd.hzmkYpjbIV/Render GIT_SHARE_BASE_DIR=/builds/git-shared HG_SHARE_BASE_DIR=/builds/hg-shared HOME=/Users/cltbld IDLEIZER_DISABLE_SHUTDOWN=true LOGNAME=cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NO_EM_RESTART=1 PAGER=/bin/cat PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11 PROPERTIES_FILE=/builds/slave/test/buildprops.json PWD=/builds/slave/test RUNNER_CONFIG_CMD=/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg SHELL=/bin/bash SSH_AUTH_SOCK=/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners TMPDIR=/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/ TWISTD_LOG_PATH=/builds/slave/twistd.log USER=cltbld VERSIONER_PYTHON_PREFER_32_BIT=no VERSIONER_PYTHON_VERSION=2.7 XPCOM_DEBUG_BREAK=warn XPC_FLAGS=0x0 XPC_SERVICE_NAME=0 __CF_USER_TEXT_ENCODING=0x1C:0x0:0x0 using PTY: False 14:00:56 INFO - MultiFileLogger online at 20151023 14:00:56 in /builds/slave/test 14:00:56 INFO - Run as scripts/scripts/talos_script.py --suite other --add-option --webServer,localhost --branch-name Fx-Team --system-bits 64 --cfg talos/mac_config.py --download-symbols ondemand --use-talos-json --blob-upload-branch Fx-Team 14:00:56 INFO - Dumping config to /builds/slave/test/logs/localconfig.json. 14:00:56 INFO - {'append_to_log': False, 14:00:56 INFO - 'base_work_dir': '/builds/slave/test', 14:00:56 INFO - 'blob_upload_branch': 'Fx-Team', 14:00:56 INFO - 'blob_uploader_auth_file': '/builds/slave/test/oauth.txt', 14:00:56 INFO - 'branch': 'Fx-Team', 14:00:56 INFO - 'buildbot_json_path': 'buildprops.json', 14:00:56 INFO - 'config_files': ('talos/mac_config.py',), 14:00:56 INFO - 'default_actions': ('clobber', 14:00:56 INFO - 'read-buildbot-config', 14:00:56 INFO - 'download-and-extract', 14:00:56 INFO - 'populate-webroot', 14:00:56 INFO - 'create-virtualenv', 14:00:56 INFO - 'install', 14:00:56 INFO - 'run-tests'), 14:00:56 INFO - 'default_blob_upload_servers': ('https://blobupload.elasticbeanstalk.com',), 14:00:56 INFO - 'download_minidump_stackwalk': True, 14:00:56 INFO - 'download_symbols': 'ondemand', 14:00:56 INFO - 'exes': {'python': '/tools/buildbot/bin/python', 14:00:56 INFO - 'tooltool.py': '/tools/tooltool.py', 14:00:56 INFO - 'virtualenv': ('/tools/buildbot/bin/python', 14:00:56 INFO - '/tools/misc-python/virtualenv.py')}, 14:00:56 INFO - 'find_links': ('http://pypi.pvt.build.mozilla.org/pub', 14:00:56 INFO - 'http://pypi.pub.build.mozilla.org/pub'), 14:00:56 INFO - 'installer_path': 'installer.exe', 14:00:56 INFO - 'log_level': 'info', 14:00:56 INFO - 'log_name': 'talos', 14:00:56 INFO - 'log_to_console': True, 14:00:56 INFO - 'minidump_stackwalk_path': 'macosx64-minidump_stackwalk', 14:00:56 INFO - 'minidump_tooltool_manifest_path': 'config/tooltool-manifests/macosx64/releng.manifest', 14:00:56 INFO - 'opt_config_files': (), 14:00:56 INFO - 'pip_index': False, 14:00:56 INFO - 'postflight_run_cmd_suites': ({'architectures': ('32bit', '64bit'), 14:00:56 INFO - 'cmd': ('bash', 14:00:56 INFO - '-c', 14:00:56 INFO - 'screenresolution get && screenresolution list && system_profiler SPDisplaysDataType'), 14:00:56 INFO - 'enabled': True, 14:00:56 INFO - 'halt_on_failure': False, 14:00:56 INFO - 'name': 'check_screen_resolution'},), 14:00:56 INFO - 'preflight_run_cmd_suites': ({'architectures': ('32bit', '64bit'), 14:00:56 INFO - 'cmd': ('bash', 14:00:56 INFO - '-c', 14:00:56 INFO - 'screenresolution get && screenresolution list && system_profiler SPDisplaysDataType'), 14:00:56 INFO - 'enabled': True, 14:00:56 INFO - 'halt_on_failure': False, 14:00:56 INFO - 'name': 'check_screen_resolution'},), 14:00:56 INFO - 'run_cmd_checks_enabled': True, 14:00:56 INFO - 'sps_profile': False, 14:00:56 INFO - 'sps_profile_interval': 0, 14:00:56 INFO - 'suite': 'other', 14:00:56 INFO - 'system_bits': '64', 14:00:56 INFO - 'talos_extra_options': ('--webServer', 'localhost'), 14:00:56 INFO - 'title': 't-yosemite-r5-0016', 14:00:56 INFO - 'tooltool_cache': '/builds/tooltool_cache', 14:00:56 INFO - 'use_talos_json': True, 14:00:56 INFO - 'virtualenv_path': '/builds/slave/test/build/venv', 14:00:56 INFO - 'volatile_config': {'actions': None, 'add_actions': None, 'no_actions': None}, 14:00:56 INFO - 'work_dir': 'build'} 14:00:56 INFO - ##### 14:00:56 INFO - ##### Running clobber step. 14:00:56 INFO - ##### 14:00:56 INFO - Running pre-action listener: _resource_record_pre_action 14:00:56 INFO - Running main action method: clobber 14:00:56 INFO - rmtree: /builds/slave/test/build 14:00:56 INFO - retry: Calling rmtree with args: ('/builds/slave/test/build',), kwargs: {}, attempt #1 14:01:00 INFO - Running post-action listener: _resource_record_post_action 14:01:00 INFO - ##### 14:01:00 INFO - ##### Running read-buildbot-config step. 14:01:00 INFO - ##### 14:01:00 INFO - Running pre-action listener: _resource_record_pre_action 14:01:00 INFO - Running main action method: read_buildbot_config 14:01:00 INFO - Using buildbot properties: 14:01:00 INFO - { 14:01:00 INFO - "properties": { 14:01:00 INFO - "buildnumber": 205, 14:01:00 INFO - "product": "firefox", 14:01:00 INFO - "script_repo_revision": "production", 14:01:00 INFO - "builddir": "fx-team_yosemite_test-other", 14:01:00 INFO - "repository": "", 14:01:00 INFO - "buildername": "Rev5 MacOSX Yosemite 10.10 fx-team talos other", 14:01:00 INFO - "buildid": "20151023121232", 14:01:00 INFO - "slavename": "t-yosemite-r5-0016", 14:01:00 INFO - "pgo_build": "False", 14:01:00 INFO - "basedir": "/builds/slave/test", 14:01:00 INFO - "project": "", 14:01:00 INFO - "platform": "yosemite", 14:01:00 INFO - "master": "http://buildbot-master107.bb.releng.scl3.mozilla.com:8201/", 14:01:00 INFO - "slavebuilddir": "test", 14:01:00 INFO - "scheduler": "tests-fx-team-macosx64-talos", 14:01:00 INFO - "branch": "fx-team", 14:01:00 INFO - "repo_path": "integration/fx-team", 14:01:00 INFO - "stage_platform": "macosx64", 14:01:00 INFO - "builduid": "70c1a8410c6f4d2891f361e5be11844c", 14:01:00 INFO - "revision": "ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc" 14:01:00 INFO - }, 14:01:00 INFO - "sourcestamp": { 14:01:00 INFO - "repository": "", 14:01:00 INFO - "hasPatch": false, 14:01:00 INFO - "project": "", 14:01:00 INFO - "branch": "fx-team-macosx64-talos", 14:01:00 INFO - "changes": [ 14:01:00 INFO - { 14:01:00 INFO - "category": null, 14:01:00 INFO - "files": [ 14:01:00 INFO - { 14:01:00 INFO - "url": null, 14:01:00 INFO - "name": "https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.dmg" 14:01:00 INFO - } 14:01:00 INFO - ], 14:01:00 INFO - "repository": "", 14:01:00 INFO - "rev": "ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc", 14:01:00 INFO - "who": "dtownsend@mozilla.com", 14:01:00 INFO - "when": 1445633444, 14:01:00 INFO - "number": 6567866, 14:01:00 INFO - "comments": "Bug 1217070: Fix accessing the bootstrap methods when they are declared in the new lexical scope. r=rhelmer\n\nRather that trying to get the method from the sandbox global object which will\nonly work for var and function declared methods instead evaluate the function\nname in the sandbox scope and get the result which will give us access to the\nlexical scope.", 14:01:00 INFO - "project": "", 14:01:00 INFO - "at": "Fri 23 Oct 2015 13:50:44", 14:01:00 INFO - "branch": "fx-team-macosx64-talos", 14:01:00 INFO - "revlink": "", 14:01:00 INFO - "properties": [ 14:01:00 INFO - [ 14:01:00 INFO - "buildid", 14:01:00 INFO - "20151023121232", 14:01:00 INFO - "Change" 14:01:00 INFO - ], 14:01:00 INFO - [ 14:01:00 INFO - "builduid", 14:01:00 INFO - "70c1a8410c6f4d2891f361e5be11844c", 14:01:00 INFO - "Change" 14:01:00 INFO - ], 14:01:00 INFO - [ 14:01:00 INFO - "pgo_build", 14:01:00 INFO - "False", 14:01:00 INFO - "Change" 14:01:00 INFO - ] 14:01:00 INFO - ], 14:01:00 INFO - "revision": "ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc" 14:01:00 INFO - } 14:01:00 INFO - ], 14:01:00 INFO - "revision": "ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc" 14:01:00 INFO - } 14:01:00 INFO - } 14:01:00 INFO - Found installer url https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.dmg. 14:01:00 INFO - Running post-action listener: _resource_record_post_action 14:01:00 INFO - ##### 14:01:00 INFO - ##### Running download-and-extract step. 14:01:00 INFO - ##### 14:01:00 INFO - Running pre-action listener: _resource_record_pre_action 14:01:00 INFO - Running main action method: download_and_extract 14:01:00 INFO - mkdir: /builds/slave/test/build/tests 14:01:00 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')]} 14:01:00 INFO - https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/test_packages.json matches https://queue.taskcluster.net 14:01:00 INFO - URL Candidate: http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/test_packages.json 14:01:00 INFO - trying http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/test_packages.json 14:01:00 INFO - Downloading http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/test_packages.json to /builds/slave/test/build/test_packages.json 14:01:00 INFO - retry: Calling _download_file with args: (), kwargs: {'url': 'http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/test_packages.json', 'file_name': '/builds/slave/test/build/test_packages.json'}, attempt #1 14:01:00 INFO - Downloaded 1149 bytes. 14:01:00 INFO - Reading from file /builds/slave/test/build/test_packages.json 14:01:00 INFO - Using the following test package requirements: 14:01:00 INFO - {u'common': [u'firefox-44.0a1.en-US.mac.common.tests.zip'], 14:01:00 INFO - u'cppunittest': [u'firefox-44.0a1.en-US.mac.common.tests.zip', 14:01:00 INFO - u'firefox-44.0a1.en-US.mac.cppunittest.tests.zip'], 14:01:00 INFO - u'jittest': [u'firefox-44.0a1.en-US.mac.common.tests.zip', 14:01:00 INFO - u'jsshell-mac.zip'], 14:01:00 INFO - u'mochitest': [u'firefox-44.0a1.en-US.mac.common.tests.zip', 14:01:00 INFO - u'firefox-44.0a1.en-US.mac.mochitest.tests.zip'], 14:01:00 INFO - u'mozbase': [u'firefox-44.0a1.en-US.mac.common.tests.zip'], 14:01:00 INFO - u'reftest': [u'firefox-44.0a1.en-US.mac.common.tests.zip', 14:01:00 INFO - u'firefox-44.0a1.en-US.mac.reftest.tests.zip'], 14:01:00 INFO - u'talos': [u'firefox-44.0a1.en-US.mac.common.tests.zip', 14:01:00 INFO - u'firefox-44.0a1.en-US.mac.talos.tests.zip'], 14:01:00 INFO - u'web-platform': [u'firefox-44.0a1.en-US.mac.common.tests.zip', 14:01:00 INFO - u'firefox-44.0a1.en-US.mac.web-platform.tests.zip'], 14:01:00 INFO - u'webapprt': [u'firefox-44.0a1.en-US.mac.common.tests.zip'], 14:01:00 INFO - u'xpcshell': [u'firefox-44.0a1.en-US.mac.common.tests.zip', 14:01:00 INFO - u'firefox-44.0a1.en-US.mac.xpcshell.tests.zip']} 14:01:00 INFO - Downloading packages: [u'firefox-44.0a1.en-US.mac.common.tests.zip'] for test suite category: common 14:01:00 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')]} 14:01:00 INFO - https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.common.tests.zip matches https://queue.taskcluster.net 14:01:00 INFO - URL Candidate: http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.common.tests.zip 14:01:00 INFO - trying http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.common.tests.zip 14:01:00 INFO - Downloading http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.common.tests.zip to /builds/slave/test/build/firefox-44.0a1.en-US.mac.common.tests.zip 14:01:00 INFO - retry: Calling _download_file with args: (), kwargs: {'url': u'http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.common.tests.zip', 'file_name': u'/builds/slave/test/build/firefox-44.0a1.en-US.mac.common.tests.zip'}, attempt #1 14:01:01 INFO - Downloaded 17447745 bytes. 14:01:01 INFO - Running command: ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-44.0a1.en-US.mac.common.tests.zip'] in /builds/slave/test/build/tests 14:01:01 INFO - Copy/paste: unzip -q -o /builds/slave/test/build/firefox-44.0a1.en-US.mac.common.tests.zip 14:01:01 INFO - Calling ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-44.0a1.en-US.mac.common.tests.zip'] with output_timeout 1760 14:01:06 INFO - Return code: 0 14:01:06 INFO - Downloading packages: [u'firefox-44.0a1.en-US.mac.common.tests.zip', u'firefox-44.0a1.en-US.mac.talos.tests.zip'] for test suite category: talos 14:01: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')]} 14:01:06 INFO - https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.common.tests.zip matches https://queue.taskcluster.net 14:01:06 INFO - URL Candidate: http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.common.tests.zip 14:01:06 INFO - trying http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.common.tests.zip 14:01:06 INFO - Downloading http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.common.tests.zip to /builds/slave/test/build/firefox-44.0a1.en-US.mac.common.tests.zip 14:01:06 INFO - retry: Calling _download_file with args: (), kwargs: {'url': u'http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.common.tests.zip', 'file_name': u'/builds/slave/test/build/firefox-44.0a1.en-US.mac.common.tests.zip'}, attempt #1 14:01:09 INFO - Downloaded 17447745 bytes. 14:01:09 INFO - Running command: ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-44.0a1.en-US.mac.common.tests.zip'] in /builds/slave/test/build/tests 14:01:09 INFO - Copy/paste: unzip -q -o /builds/slave/test/build/firefox-44.0a1.en-US.mac.common.tests.zip 14:01:09 INFO - Calling ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-44.0a1.en-US.mac.common.tests.zip'] with output_timeout 1760 14:01:13 INFO - Return code: 0 14:01:13 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')]} 14:01:13 INFO - https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.talos.tests.zip matches https://queue.taskcluster.net 14:01:13 INFO - URL Candidate: http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.talos.tests.zip 14:01:13 INFO - trying http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.talos.tests.zip 14:01:13 INFO - Downloading http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.talos.tests.zip to /builds/slave/test/build/firefox-44.0a1.en-US.mac.talos.tests.zip 14:01:13 INFO - retry: Calling _download_file with args: (), kwargs: {'url': u'http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.talos.tests.zip', 'file_name': u'/builds/slave/test/build/firefox-44.0a1.en-US.mac.talos.tests.zip'}, attempt #1 14:01:17 INFO - Downloaded 11131307 bytes. 14:01:17 INFO - Running command: ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-44.0a1.en-US.mac.talos.tests.zip'] in /builds/slave/test/build/tests 14:01:17 INFO - Copy/paste: unzip -q -o /builds/slave/test/build/firefox-44.0a1.en-US.mac.talos.tests.zip 14:01:17 INFO - Calling ['unzip', '-q', '-o', u'/builds/slave/test/build/firefox-44.0a1.en-US.mac.talos.tests.zip'] with output_timeout 1760 14:01:18 INFO - Return code: 0 14:01:18 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')]} 14:01:18 INFO - https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.dmg matches https://queue.taskcluster.net 14:01:18 INFO - URL Candidate: http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.dmg 14:01:18 INFO - trying http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.dmg 14:01:18 INFO - Downloading http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.dmg to /builds/slave/test/build/firefox-44.0a1.en-US.mac.dmg 14:01:18 INFO - retry: Calling _download_file with args: (), kwargs: {'url': 'http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.dmg', 'file_name': '/builds/slave/test/build/firefox-44.0a1.en-US.mac.dmg'}, attempt #1 14:01:21 INFO - Downloaded 108352699 bytes. 14:01:21 INFO - Setting buildbot property build_url to https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.dmg 14:01:21 INFO - mkdir: /builds/slave/test/properties 14:01:21 INFO - Writing buildbot properties ['build_url'] to /builds/slave/test/properties/build_url 14:01:21 INFO - Writing to file /builds/slave/test/properties/build_url 14:01:21 INFO - Contents: 14:01:21 INFO - build_url:https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.dmg 14:01:21 INFO - Running post-action listener: _resource_record_post_action 14:01:21 INFO - Running post-action listener: set_extra_try_arguments 14:01:21 INFO - ##### 14:01:21 INFO - ##### Running populate-webroot step. 14:01:21 INFO - ##### 14:01:21 INFO - Running pre-action listener: _resource_record_pre_action 14:01:21 INFO - Running main action method: populate_webroot 14:01:21 INFO - Guessing talos json url... 14:01:21 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')]} 14:01:21 INFO - https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.txt matches https://queue.taskcluster.net 14:01:21 INFO - URL Candidate: http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.txt 14:01:21 INFO - trying http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.txt 14:01:21 INFO - Downloading http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.txt to /builds/slave/test/build/firefox-44.0a1.en-US.mac.txt 14:01:21 INFO - retry: Calling _download_file with args: (), kwargs: {'url': 'http://queue.taskcluster.net.proxxy1.srv.releng.scl3.mozilla.com/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.txt', 'file_name': '/builds/slave/test/build/firefox-44.0a1.en-US.mac.txt'}, attempt #1 14:01:21 INFO - Downloaded 103 bytes. 14:01:21 INFO - Reading from file /builds/slave/test/build/firefox-44.0a1.en-US.mac.txt 14:01:21 INFO - Contents: 14:01:21 INFO - 20151023121232 14:01:21 INFO - https://hg.mozilla.org/integration/fx-team/rev/ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc 14:01:21 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')]} 14:01:21 INFO - trying https://hg.mozilla.org/integration/fx-team/raw-file/ccb7bb578f/testing/talos/talos.json 14:01:21 INFO - Downloading https://hg.mozilla.org/integration/fx-team/raw-file/ccb7bb578f/testing/talos/talos.json to /builds/slave/test/build/talos.json 14:01:21 INFO - retry: Calling _download_file with args: (), kwargs: {'url': 'https://hg.mozilla.org/integration/fx-team/raw-file/ccb7bb578f/testing/talos/talos.json', 'file_name': '/builds/slave/test/build/talos.json'}, attempt #1 14:01:22 INFO - Downloaded 4264 bytes. 14:01:22 INFO - {'extra_options': {'android': ['--apkPath=%(apk_path)s']}, 14:01:22 INFO - 'mobile-suites': {'remote-tp4m_nochrome': {'tests': ['tp4m']}, 14:01:22 INFO - 'remote-trobocheck2': {'talos_options': ['--fennecIDs', 14:01:22 INFO - '../fennec_ids.txt'], 14:01:22 INFO - 'tests': ['tcheck2']}, 14:01:22 INFO - 'remote-tsvgx': {'talos_options': ['--noChrome', 14:01:22 INFO - '--tppagecycles', 14:01:22 INFO - '7'], 14:01:22 INFO - 'tests': ['tsvgm']}}, 14:01:22 INFO - 'suites': {'chromez': {'tests': ['tresize', 'tcanvasmark']}, 14:01:22 INFO - 'chromez-e10s': {'talos_options': ['--e10s'], 14:01:22 INFO - 'tests': ['tresize', 'tcanvasmark']}, 14:01:22 INFO - 'dromaeojs': {'tests': ['dromaeo_css', 'kraken', 'v8_7']}, 14:01:22 INFO - 'dromaeojs-e10s': {'talos_options': ['--e10s'], 14:01:22 INFO - 'tests': ['dromaeo_css', 'kraken', 'v8_7']}, 14:01:22 INFO - 'g1': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 14:01:22 INFO - 'tests': ['tp5o_scroll', 'glterrain']}, 14:01:22 INFO - 'g1-e10s': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 14:01:22 INFO - 'talos_options': ['--e10s'], 14:01:22 INFO - 'tests': ['tp5o_scroll', 'glterrain']}, 14:01:22 INFO - 'g2': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 14:01:22 INFO - 'tests': ['damp', 'tps']}, 14:01:22 INFO - 'g2-e10s': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 14:01:22 INFO - 'talos_options': ['--e10s'], 14:01:22 INFO - 'tests': ['damp', 'tps']}, 14:01:22 INFO - 'g3': {'tests': ['dromaeo_dom']}, 14:01:22 INFO - 'g3-e10s': {'tests': ['dromaeo_dom']}, 14:01:22 INFO - 'other': {'tests': ['a11yr', 14:01:22 INFO - 'ts_paint', 14:01:22 INFO - 'tpaint', 14:01:22 INFO - 'sessionrestore', 14:01:22 INFO - 'sessionrestore_no_auto_restore']}, 14:01:22 INFO - 'other-e10s': {'talos_options': ['--e10s'], 14:01:22 INFO - 'tests': ['a11yr', 14:01:22 INFO - 'ts_paint', 14:01:22 INFO - 'tpaint', 14:01:22 INFO - 'sessionrestore', 14:01:22 INFO - 'sessionrestore_no_auto_restore']}, 14:01:22 INFO - 'other-e10s_l64': {'talos_options': ['--e10s'], 14:01:22 INFO - 'tests': ['a11yr', 14:01:22 INFO - 'ts_paint', 14:01:22 INFO - 'tpaint', 14:01:22 INFO - 'sessionrestore', 14:01:22 INFO - 'sessionrestore_no_auto_restore']}, 14:01:22 INFO - 'other-e10s_nol64': {'talos_options': ['--e10s'], 14:01:22 INFO - 'tests': ['a11yr', 14:01:22 INFO - 'ts_paint', 14:01:22 INFO - 'tpaint', 14:01:22 INFO - 'sessionrestore', 14:01:22 INFO - 'sessionrestore_no_auto_restore']}, 14:01:22 INFO - 'other_l64': {'tests': ['a11yr', 14:01:22 INFO - 'ts_paint', 14:01:22 INFO - 'tpaint', 14:01:22 INFO - 'sessionrestore', 14:01:22 INFO - 'sessionrestore_no_auto_restore']}, 14:01:22 INFO - 'other_nol64': {'tests': ['a11yr', 14:01:22 INFO - 'ts_paint', 14:01:22 INFO - 'tpaint', 14:01:22 INFO - 'sessionrestore', 14:01:22 INFO - 'sessionrestore_no_auto_restore']}, 14:01:22 INFO - 'svgr': {'tests': ['tsvgx', 14:01:22 INFO - 'tsvgr_opacity', 14:01:22 INFO - 'tart', 14:01:22 INFO - 'tscrollx', 14:01:22 INFO - 'cart']}, 14:01:22 INFO - 'svgr-e10s': {'talos_options': ['--e10s'], 14:01:22 INFO - 'tests': ['tsvgx', 14:01:22 INFO - 'tsvgr_opacity', 14:01:22 INFO - 'tart', 14:01:22 INFO - 'tscrollx', 14:01:22 INFO - 'cart']}, 14:01:22 INFO - 'tp5o': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 14:01:22 INFO - 'tests': ['tp5o']}, 14:01:22 INFO - 'tp5o-e10s': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 14:01:22 INFO - 'talos_options': ['--e10s'], 14:01:22 INFO - 'tests': ['tp5o']}, 14:01:22 INFO - 'xperf': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 14:01:22 INFO - 'talos_options': ['--xperf_path', 14:01:22 INFO - '"c:/Program Files/Microsoft Windows Performance Toolkit/xperf.exe"'], 14:01:22 INFO - 'tests': ['tp5n']}, 14:01:22 INFO - 'xperf-e10s': {'pagesets_url': 'http://talos-bundles.pvt.build.mozilla.org/zips/tp5n.zip', 14:01:22 INFO - 'talos_options': ['--e10s', 14:01:22 INFO - '--xperf_path', 14:01:22 INFO - '"c:/Program Files/Microsoft Windows Performance Toolkit/xperf.exe"', 14:01:22 INFO - 'C:/slave/talos-data/talos/xperf.config'], 14:01:22 INFO - 'tests': ['tp5n']}}, 14:01:22 INFO - 'talos.zip': {'path': '', 14:01:22 INFO - 'url': 'http://talos-bundles.pvt.build.mozilla.org/zips/talos.a6052c33d420.zip'}} 14:01:22 INFO - Running post-action listener: _resource_record_post_action 14:01:22 INFO - ##### 14:01:22 INFO - ##### Running create-virtualenv step. 14:01:22 INFO - ##### 14:01:22 INFO - Running pre-action listener: _resource_record_pre_action 14:01:22 INFO - Running main action method: create_virtualenv 14:01:22 INFO - Creating virtualenv /builds/slave/test/build/venv 14:01:22 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 14:01:22 INFO - Copy/paste: /tools/buildbot/bin/python /tools/misc-python/virtualenv.py --no-site-packages --distribute /builds/slave/test/build/venv 14:01:22 INFO - The --no-site-packages flag is deprecated; it is now the default behavior. 14:01:22 INFO - Using real prefix '/tools/python27' 14:01:22 INFO - New python executable in /builds/slave/test/build/venv/bin/python 14:01:23 INFO - Installing distribute.............................................................................................................................................................................................done. 14:01:26 INFO - Installing pip.................done. 14:01:26 INFO - Return code: 0 14:01:26 INFO - Installing pip>=1.5 into virtualenv /builds/slave/test/build/venv 14:01:26 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')]} 14:01:26 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 14:01:26 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:26 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')]} 14:01:26 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 14:01:26 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:26 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 0x105fbda30>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x10602a228>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7fd45358f8c0>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x105f729f0>, '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 0x105cd1cd8>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x105f3c990>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build', 'env': {'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'XPC_SERVICE_NAME': '0', 'HOME': '/Users/cltbld', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 'NO_EM_RESTART': '1', 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 'XPCOM_DEBUG_BREAK': 'warn', 'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 'VERSIONER_PYTHON_VERSION': '2.7', 'XPC_FLAGS': '0x0', 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 'MOZ_NO_REMOTE': '1', 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 'SHELL': '/bin/bash', 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0', 'PWD': '/builds/slave/test', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'PAGER': '/bin/cat'}}, attempt #1 14:01:26 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 14:01:26 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 14:01:26 INFO - Using env: {'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 14:01:26 INFO - 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 14:01:26 INFO - 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 14:01:26 INFO - 'HOME': '/Users/cltbld', 14:01:26 INFO - 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 14:01:26 INFO - 'LOGNAME': 'cltbld', 14:01:26 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 14:01:26 INFO - 'MOZ_NO_REMOTE': '1', 14:01:26 INFO - 'NO_EM_RESTART': '1', 14:01:26 INFO - 'PAGER': '/bin/cat', 14:01:26 INFO - 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 14:01:26 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 14:01:26 INFO - 'PWD': '/builds/slave/test', 14:01:26 INFO - 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 14:01:26 INFO - 'SHELL': '/bin/bash', 14:01:26 INFO - 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 14:01:26 INFO - 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', 14:01:26 INFO - 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 14:01:26 INFO - 'USER': 'cltbld', 14:01:26 INFO - 'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 14:01:26 INFO - 'VERSIONER_PYTHON_VERSION': '2.7', 14:01:26 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 14:01:26 INFO - 'XPC_FLAGS': '0x0', 14:01:26 INFO - 'XPC_SERVICE_NAME': '0', 14:01:26 INFO - '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0'} 14:01:27 INFO - Ignoring indexes: https://pypi.python.org/simple/ 14:01:27 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 14:01:27 INFO - Cleaning up... 14:01:27 INFO - Return code: 0 14:01:27 INFO - Installing psutil>=0.7.1 into virtualenv /builds/slave/test/build/venv 14:01:27 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')]} 14:01:27 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 14:01:27 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:27 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')]} 14:01:27 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 14:01:27 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:27 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 0x105fbda30>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x10602a228>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7fd45358f8c0>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x105f729f0>, '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 0x105cd1cd8>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x105f3c990>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build', 'env': {'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'XPC_SERVICE_NAME': '0', 'HOME': '/Users/cltbld', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 'NO_EM_RESTART': '1', 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 'XPCOM_DEBUG_BREAK': 'warn', 'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 'VERSIONER_PYTHON_VERSION': '2.7', 'XPC_FLAGS': '0x0', 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 'MOZ_NO_REMOTE': '1', 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 'SHELL': '/bin/bash', 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0', 'PWD': '/builds/slave/test', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'PAGER': '/bin/cat'}}, attempt #1 14:01:27 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 14:01:27 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 14:01:27 INFO - Using env: {'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 14:01:27 INFO - 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 14:01:27 INFO - 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 14:01:27 INFO - 'HOME': '/Users/cltbld', 14:01:27 INFO - 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 14:01:27 INFO - 'LOGNAME': 'cltbld', 14:01:27 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 14:01:27 INFO - 'MOZ_NO_REMOTE': '1', 14:01:27 INFO - 'NO_EM_RESTART': '1', 14:01:27 INFO - 'PAGER': '/bin/cat', 14:01:27 INFO - 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 14:01:27 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 14:01:27 INFO - 'PWD': '/builds/slave/test', 14:01:27 INFO - 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 14:01:27 INFO - 'SHELL': '/bin/bash', 14:01:27 INFO - 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 14:01:27 INFO - 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', 14:01:27 INFO - 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 14:01:27 INFO - 'USER': 'cltbld', 14:01:27 INFO - 'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 14:01:27 INFO - 'VERSIONER_PYTHON_VERSION': '2.7', 14:01:27 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 14:01:27 INFO - 'XPC_FLAGS': '0x0', 14:01:27 INFO - 'XPC_SERVICE_NAME': '0', 14:01:27 INFO - '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0'} 14:01:27 INFO - Ignoring indexes: https://pypi.python.org/simple/ 14:01:27 INFO - Downloading/unpacking psutil>=0.7.1 14:01:27 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 14:01:27 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 14:01:27 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 14:01:27 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 14:01:27 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 14:01:27 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 14:01:29 INFO - Creating supposed download cache at /builds/slave/test/build/venv/cache 14:01:29 INFO - Storing download in cache at ./venv/cache/http%3A%2F%2Fpypi.pvt.build.mozilla.org%2Fpub%2Fpsutil-3.1.1.tar.gz 14:01:29 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/psutil/setup.py) egg_info for package psutil 14:01:29 INFO - warning: no previously-included files matching '*' found under directory 'docs/_build' 14:01:29 INFO - warning: manifest_maker: MANIFEST.in, line 18: 'recursive-include' expects ... 14:01:29 INFO - Installing collected packages: psutil 14:01:29 INFO - Running setup.py install for psutil 14:01:30 INFO - building 'psutil._psutil_osx' extension 14:01:30 INFO - gcc -fno-strict-aliasing -g -O2 -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes -DPSUTIL_VERSION=311 -I/tools/python27/include/python2.7 -c psutil/_psutil_osx.c -o build/temp.macosx-10.10-x86_64-2.7/psutil/_psutil_osx.o 14:01:31 INFO - gcc -fno-strict-aliasing -g -O2 -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes -DPSUTIL_VERSION=311 -I/tools/python27/include/python2.7 -c psutil/_psutil_common.c -o build/temp.macosx-10.10-x86_64-2.7/psutil/_psutil_common.o 14:01:31 INFO - gcc -fno-strict-aliasing -g -O2 -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes -DPSUTIL_VERSION=311 -I/tools/python27/include/python2.7 -c psutil/arch/osx/process_info.c -o build/temp.macosx-10.10-x86_64-2.7/psutil/arch/osx/process_info.o 14:01:31 INFO - gcc -bundle -bundle_loader /tools/python27/bin/python2.7 build/temp.macosx-10.10-x86_64-2.7/psutil/_psutil_osx.o build/temp.macosx-10.10-x86_64-2.7/psutil/_psutil_common.o build/temp.macosx-10.10-x86_64-2.7/psutil/arch/osx/process_info.o -o build/lib.macosx-10.10-x86_64-2.7/psutil/_psutil_osx.so -framework CoreFoundation -framework IOKit 14:01:32 INFO - building 'psutil._psutil_posix' extension 14:01:32 INFO - gcc -fno-strict-aliasing -g -O2 -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes -I/tools/python27/include/python2.7 -c psutil/_psutil_posix.c -o build/temp.macosx-10.10-x86_64-2.7/psutil/_psutil_posix.o 14:01:32 WARNING - psutil/_psutil_posix.c:403:11: warning: implicit declaration of function 'ioctl' is invalid in C99 [-Wimplicit-function-declaration] 14:01:32 INFO - ret = ioctl(sock, SIOCGIFFLAGS, &ifr); 14:01:32 INFO - ^ 14:01:32 INFO - 1 warning generated. 14:01:32 INFO - gcc -bundle -bundle_loader /tools/python27/bin/python2.7 build/temp.macosx-10.10-x86_64-2.7/psutil/_psutil_posix.o -o build/lib.macosx-10.10-x86_64-2.7/psutil/_psutil_posix.so 14:01:32 INFO - warning: no previously-included files matching '*' found under directory 'docs/_build' 14:01:32 INFO - warning: manifest_maker: MANIFEST.in, line 18: 'recursive-include' expects ... 14:01:32 INFO - Successfully installed psutil 14:01:32 INFO - Cleaning up... 14:01:32 INFO - Return code: 0 14:01:32 INFO - Installing mozsystemmonitor==0.0.0 into virtualenv /builds/slave/test/build/venv 14:01: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')]} 14:01:32 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 14:01:32 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01: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')]} 14:01:32 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 14:01:32 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01: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', '--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 0x105fbda30>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x10602a228>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7fd45358f8c0>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x105f729f0>, '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 0x105cd1cd8>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x105f3c990>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build', 'env': {'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'XPC_SERVICE_NAME': '0', 'HOME': '/Users/cltbld', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 'NO_EM_RESTART': '1', 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 'XPCOM_DEBUG_BREAK': 'warn', 'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 'VERSIONER_PYTHON_VERSION': '2.7', 'XPC_FLAGS': '0x0', 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 'MOZ_NO_REMOTE': '1', 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 'SHELL': '/bin/bash', 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0', 'PWD': '/builds/slave/test', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'PAGER': '/bin/cat'}}, attempt #1 14:01:32 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 14:01:32 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 14:01:32 INFO - Using env: {'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 14:01:32 INFO - 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 14:01:32 INFO - 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 14:01:32 INFO - 'HOME': '/Users/cltbld', 14:01:32 INFO - 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 14:01:32 INFO - 'LOGNAME': 'cltbld', 14:01:32 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 14:01:32 INFO - 'MOZ_NO_REMOTE': '1', 14:01:32 INFO - 'NO_EM_RESTART': '1', 14:01:32 INFO - 'PAGER': '/bin/cat', 14:01:32 INFO - 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 14:01:32 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 14:01:32 INFO - 'PWD': '/builds/slave/test', 14:01:32 INFO - 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 14:01:32 INFO - 'SHELL': '/bin/bash', 14:01:32 INFO - 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 14:01:32 INFO - 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', 14:01:32 INFO - 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 14:01:32 INFO - 'USER': 'cltbld', 14:01:32 INFO - 'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 14:01:32 INFO - 'VERSIONER_PYTHON_VERSION': '2.7', 14:01:32 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 14:01:32 INFO - 'XPC_FLAGS': '0x0', 14:01:32 INFO - 'XPC_SERVICE_NAME': '0', 14:01:32 INFO - '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0'} 14:01:32 INFO - Ignoring indexes: https://pypi.python.org/simple/ 14:01:32 INFO - Downloading/unpacking mozsystemmonitor==0.0.0 14:01:32 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 14:01:32 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 14:01:32 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 14:01:32 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 14:01:32 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 14:01:32 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 14:01:35 INFO - Downloading mozsystemmonitor-0.0.tar.gz 14:01:35 INFO - Storing download in cache at ./venv/cache/http%3A%2F%2Fpypi.pvt.build.mozilla.org%2Fpub%2Fmozsystemmonitor-0.0.tar.gz 14:01:35 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/mozsystemmonitor/setup.py) egg_info for package mozsystemmonitor 14:01:35 INFO - Requirement already satisfied (use --upgrade to upgrade): psutil>=0.7.1 in ./venv/lib/python2.7/site-packages (from mozsystemmonitor==0.0.0) 14:01:35 INFO - Installing collected packages: mozsystemmonitor 14:01:35 INFO - Running setup.py install for mozsystemmonitor 14:01:35 INFO - Successfully installed mozsystemmonitor 14:01:35 INFO - Cleaning up... 14:01:35 INFO - Return code: 0 14:01:35 INFO - Installing blobuploader==1.2.4 into virtualenv /builds/slave/test/build/venv 14:01:35 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')]} 14:01:35 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 14:01:35 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:35 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')]} 14:01:35 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 14:01:35 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:35 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 0x105fbda30>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x10602a228>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7fd45358f8c0>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x105f729f0>, '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 0x105cd1cd8>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x105f3c990>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build', 'env': {'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'XPC_SERVICE_NAME': '0', 'HOME': '/Users/cltbld', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 'NO_EM_RESTART': '1', 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 'XPCOM_DEBUG_BREAK': 'warn', 'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 'VERSIONER_PYTHON_VERSION': '2.7', 'XPC_FLAGS': '0x0', 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 'MOZ_NO_REMOTE': '1', 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 'SHELL': '/bin/bash', 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0', 'PWD': '/builds/slave/test', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'PAGER': '/bin/cat'}}, attempt #1 14:01:35 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 14:01:35 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 14:01:35 INFO - Using env: {'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 14:01:35 INFO - 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 14:01:35 INFO - 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 14:01:35 INFO - 'HOME': '/Users/cltbld', 14:01:35 INFO - 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 14:01:35 INFO - 'LOGNAME': 'cltbld', 14:01:35 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 14:01:35 INFO - 'MOZ_NO_REMOTE': '1', 14:01:35 INFO - 'NO_EM_RESTART': '1', 14:01:35 INFO - 'PAGER': '/bin/cat', 14:01:35 INFO - 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 14:01:35 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 14:01:35 INFO - 'PWD': '/builds/slave/test', 14:01:35 INFO - 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 14:01:35 INFO - 'SHELL': '/bin/bash', 14:01:35 INFO - 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 14:01:35 INFO - 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', 14:01:35 INFO - 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 14:01:35 INFO - 'USER': 'cltbld', 14:01:35 INFO - 'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 14:01:35 INFO - 'VERSIONER_PYTHON_VERSION': '2.7', 14:01:35 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 14:01:35 INFO - 'XPC_FLAGS': '0x0', 14:01:35 INFO - 'XPC_SERVICE_NAME': '0', 14:01:35 INFO - '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0'} 14:01:35 INFO - Ignoring indexes: https://pypi.python.org/simple/ 14:01:35 INFO - Downloading/unpacking blobuploader==1.2.4 14:01:35 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 14:01:35 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 14:01:35 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 14:01:35 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 14:01:35 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 14:01:35 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 14:01:38 INFO - Downloading blobuploader-1.2.4.tar.gz 14:01:38 INFO - Storing download in cache at ./venv/cache/http%3A%2F%2Fpypi.pvt.build.mozilla.org%2Fpub%2Fblobuploader-1.2.4.tar.gz 14:01:38 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/blobuploader/setup.py) egg_info for package blobuploader 14:01:38 INFO - Downloading/unpacking requests==1.2.3. (from blobuploader==1.2.4) 14:01:38 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 14:01:38 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 14:01:38 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 14:01:38 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 14:01:38 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 14:01:38 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 14:01:38 INFO - Storing download in cache at ./venv/cache/http%3A%2F%2Fpypi.pvt.build.mozilla.org%2Fpub%2Frequests-1.2.3.tar.gz 14:01:38 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/requests/setup.py) egg_info for package requests 14:01:38 INFO - Downloading/unpacking docopt==0.6.1 (from blobuploader==1.2.4) 14:01:38 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 14:01:38 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 14:01:38 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 14:01:38 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 14:01:38 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 14:01:38 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 14:01:39 INFO - Downloading docopt-0.6.1.tar.gz 14:01:39 INFO - Storing download in cache at ./venv/cache/http%3A%2F%2Fpypi.pvt.build.mozilla.org%2Fpub%2Fdocopt-0.6.1.tar.gz 14:01:39 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/docopt/setup.py) egg_info for package docopt 14:01:39 INFO - Installing collected packages: blobuploader, requests, docopt 14:01:39 INFO - Running setup.py install for blobuploader 14:01:39 INFO - changing mode of build/scripts-2.7/blobberc.py from 664 to 775 14:01:39 INFO - changing mode of /builds/slave/test/build/venv/bin/blobberc.py to 775 14:01:39 INFO - Running setup.py install for requests 14:01:40 INFO - Running setup.py install for docopt 14:01:40 INFO - Successfully installed blobuploader requests docopt 14:01:40 INFO - Cleaning up... 14:01:40 INFO - Return code: 0 14:01:40 INFO - Installing None into virtualenv /builds/slave/test/build/venv 14:01:40 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')]} 14:01:40 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 14:01:40 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:40 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')]} 14:01:40 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 14:01:40 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:40 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 0x105fbda30>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x10602a228>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7fd45358f8c0>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x105f729f0>, '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 0x105cd1cd8>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x105f3c990>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build/tests/config', 'env': {'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'XPC_SERVICE_NAME': '0', 'HOME': '/Users/cltbld', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 'NO_EM_RESTART': '1', 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 'XPCOM_DEBUG_BREAK': 'warn', 'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 'VERSIONER_PYTHON_VERSION': '2.7', 'XPC_FLAGS': '0x0', 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 'MOZ_NO_REMOTE': '1', 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 'SHELL': '/bin/bash', 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0', 'PWD': '/builds/slave/test', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'PAGER': '/bin/cat'}}, attempt #1 14:01:40 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 14:01:40 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 14:01:40 INFO - Using env: {'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 14:01:40 INFO - 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 14:01:40 INFO - 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 14:01:40 INFO - 'HOME': '/Users/cltbld', 14:01:40 INFO - 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 14:01:40 INFO - 'LOGNAME': 'cltbld', 14:01:40 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 14:01:40 INFO - 'MOZ_NO_REMOTE': '1', 14:01:40 INFO - 'NO_EM_RESTART': '1', 14:01:40 INFO - 'PAGER': '/bin/cat', 14:01:40 INFO - 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 14:01:40 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 14:01:40 INFO - 'PWD': '/builds/slave/test', 14:01:40 INFO - 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 14:01:40 INFO - 'SHELL': '/bin/bash', 14:01:40 INFO - 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 14:01:40 INFO - 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', 14:01:40 INFO - 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 14:01:40 INFO - 'USER': 'cltbld', 14:01:40 INFO - 'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 14:01:40 INFO - 'VERSIONER_PYTHON_VERSION': '2.7', 14:01:40 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 14:01:40 INFO - 'XPC_FLAGS': '0x0', 14:01:40 INFO - 'XPC_SERVICE_NAME': '0', 14:01:40 INFO - '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0'} 14:01:40 INFO - Ignoring indexes: https://pypi.python.org/simple/ 14:01:40 INFO - Unpacking /builds/slave/test/build/tests/mozbase/manifestparser 14:01:40 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-DuNfaL-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/manifestparser 14:01:40 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozcrash 14:01:40 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-RY1ojX-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozcrash 14:01:40 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozdebug 14:01:40 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-g6L2pT-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozdebug 14:01:40 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozdevice 14:01:40 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-2ZUfZl-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozdevice 14:01:41 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozfile 14:01:41 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-IC1LhK-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozfile 14:01:41 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozhttpd 14:01:41 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-VTy_Y3-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozhttpd 14:01:41 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozinfo 14:01:41 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-TYwqep-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozinfo 14:01:41 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozinstall 14:01:41 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-_gooNk-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozinstall 14:01:41 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozleak 14:01:41 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-JCG7lf-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozleak 14:01:41 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozlog 14:01:41 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-2BbAOx-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozlog 14:01:41 INFO - Unpacking /builds/slave/test/build/tests/mozbase/moznetwork 14:01:41 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-qIhBYZ-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/moznetwork 14:01:41 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozprocess 14:01:41 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-C5dvNU-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozprocess 14:01:41 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozprofile 14:01:41 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-9dTK2A-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozprofile 14:01:42 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozrunner 14:01:42 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-EByyS1-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozrunner 14:01:42 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozscreenshot 14:01:42 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-l0xkbF-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozscreenshot 14:01:42 INFO - Unpacking /builds/slave/test/build/tests/mozbase/moztest 14:01:42 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-gqI2yj-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/moztest 14:01:42 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozversion 14:01:42 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-YrTHu9-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozversion 14:01:42 INFO - Installing collected packages: manifestparser, mozcrash, mozdebug, mozdevice, mozfile, mozhttpd, mozinfo, mozInstall, mozleak, mozlog, moznetwork, mozprocess, mozprofile, mozrunner, mozscreenshot, moztest, mozversion 14:01:42 INFO - Running setup.py install for manifestparser 14:01:42 INFO - Installing manifestparser script to /builds/slave/test/build/venv/bin 14:01:42 INFO - Running setup.py install for mozcrash 14:01:42 INFO - Running setup.py install for mozdebug 14:01:43 INFO - Running setup.py install for mozdevice 14:01:43 INFO - Installing sutini script to /builds/slave/test/build/venv/bin 14:01:43 INFO - Installing dm script to /builds/slave/test/build/venv/bin 14:01:43 INFO - Running setup.py install for mozfile 14:01:43 INFO - Running setup.py install for mozhttpd 14:01:43 INFO - Installing mozhttpd script to /builds/slave/test/build/venv/bin 14:01:43 INFO - Running setup.py install for mozinfo 14:01:43 INFO - Installing mozinfo script to /builds/slave/test/build/venv/bin 14:01:43 INFO - Running setup.py install for mozInstall 14:01:43 INFO - Installing moz_remove_from_system script to /builds/slave/test/build/venv/bin 14:01:43 INFO - Installing mozuninstall script to /builds/slave/test/build/venv/bin 14:01:43 INFO - Installing mozinstall script to /builds/slave/test/build/venv/bin 14:01:43 INFO - Installing moz_add_to_system script to /builds/slave/test/build/venv/bin 14:01:43 INFO - Running setup.py install for mozleak 14:01:44 INFO - Running setup.py install for mozlog 14:01:44 INFO - Installing structlog script to /builds/slave/test/build/venv/bin 14:01:44 INFO - Running setup.py install for moznetwork 14:01:44 INFO - Installing moznetwork script to /builds/slave/test/build/venv/bin 14:01:44 INFO - Running setup.py install for mozprocess 14:01:44 INFO - Running setup.py install for mozprofile 14:01:44 INFO - Installing mozprofile script to /builds/slave/test/build/venv/bin 14:01:44 INFO - Installing diff-profiles script to /builds/slave/test/build/venv/bin 14:01:44 INFO - Installing view-profile script to /builds/slave/test/build/venv/bin 14:01:44 INFO - Running setup.py install for mozrunner 14:01:44 INFO - Installing mozrunner script to /builds/slave/test/build/venv/bin 14:01:44 INFO - Running setup.py install for mozscreenshot 14:01:45 INFO - Running setup.py install for moztest 14:01:45 INFO - Running setup.py install for mozversion 14:01:45 INFO - Installing mozversion script to /builds/slave/test/build/venv/bin 14:01:45 INFO - Successfully installed manifestparser mozcrash mozdebug mozdevice mozfile mozhttpd mozinfo mozInstall mozleak mozlog moznetwork mozprocess mozprofile mozrunner mozscreenshot moztest mozversion 14:01:45 INFO - Cleaning up... 14:01:45 INFO - Return code: 0 14:01:45 INFO - Installing None into virtualenv /builds/slave/test/build/venv 14:01:45 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')]} 14:01:45 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 14:01:45 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:45 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')]} 14:01:45 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 14:01:45 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:45 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 0x105fbda30>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x10602a228>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7fd45358f8c0>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x105f729f0>, '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 0x105cd1cd8>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x105f3c990>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build/tests/config', 'env': {'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'XPC_SERVICE_NAME': '0', 'HOME': '/Users/cltbld', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 'NO_EM_RESTART': '1', 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 'XPCOM_DEBUG_BREAK': 'warn', 'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 'VERSIONER_PYTHON_VERSION': '2.7', 'XPC_FLAGS': '0x0', 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 'MOZ_NO_REMOTE': '1', 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 'SHELL': '/bin/bash', 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0', 'PWD': '/builds/slave/test', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'PAGER': '/bin/cat'}}, attempt #1 14:01:45 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 14:01:45 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 14:01:45 INFO - Using env: {'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 14:01:45 INFO - 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 14:01:45 INFO - 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 14:01:45 INFO - 'HOME': '/Users/cltbld', 14:01:45 INFO - 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 14:01:45 INFO - 'LOGNAME': 'cltbld', 14:01:45 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 14:01:45 INFO - 'MOZ_NO_REMOTE': '1', 14:01:45 INFO - 'NO_EM_RESTART': '1', 14:01:45 INFO - 'PAGER': '/bin/cat', 14:01:45 INFO - 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 14:01:45 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 14:01:45 INFO - 'PWD': '/builds/slave/test', 14:01:45 INFO - 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 14:01:45 INFO - 'SHELL': '/bin/bash', 14:01:45 INFO - 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 14:01:45 INFO - 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', 14:01:45 INFO - 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 14:01:45 INFO - 'USER': 'cltbld', 14:01:45 INFO - 'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 14:01:45 INFO - 'VERSIONER_PYTHON_VERSION': '2.7', 14:01:45 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 14:01:45 INFO - 'XPC_FLAGS': '0x0', 14:01:45 INFO - 'XPC_SERVICE_NAME': '0', 14:01:45 INFO - '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0'} 14:01:45 INFO - Ignoring indexes: https://pypi.python.org/simple/ 14:01:45 INFO - Unpacking /builds/slave/test/build/tests/mozbase/manifestparser 14:01:45 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-9YWMej-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/manifestparser 14:01:45 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)) 14:01:45 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozcrash 14:01:45 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-XcJ69Z-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozcrash 14:01:45 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)) 14:01:45 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozdebug 14:01:45 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-5CsNgQ-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozdebug 14:01:46 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)) 14:01:46 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozdevice 14:01:46 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-EriSws-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozdevice 14:01:46 INFO - Requirement already satisfied (use --upgrade to upgrade): mozdevice==0.46 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)) 14:01:46 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozfile 14:01:46 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-fM1xTF-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozfile 14:01:46 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)) 14:01:46 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozhttpd 14:01:46 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-kWYhMN-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozhttpd 14:01:46 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)) 14:01:46 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozinfo 14:01:46 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-BE7hSF-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozinfo 14:01:46 INFO - Requirement already satisfied (use --upgrade to upgrade): mozinfo==0.8 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)) 14:01:46 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozinstall 14:01:46 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-h4cmN0-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozinstall 14:01:46 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)) 14:01:46 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozleak 14:01:46 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-MMVwCP-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozleak 14:01:46 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)) 14:01:46 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozlog 14:01:46 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-mHeoGJ-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozlog 14:01:46 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)) 14:01:46 INFO - Unpacking /builds/slave/test/build/tests/mozbase/moznetwork 14:01:46 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-9PhWnF-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/moznetwork 14:01:47 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)) 14:01:47 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozprocess 14:01:47 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-Tsiq0c-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozprocess 14:01:47 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)) 14:01:47 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozprofile 14:01:47 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-12ToQO-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozprofile 14:01:47 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)) 14:01:47 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozrunner 14:01:47 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-VXhjyZ-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozrunner 14:01:47 INFO - Requirement already satisfied (use --upgrade to upgrade): mozrunner==6.10 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)) 14:01:47 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozscreenshot 14:01:47 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-BuzfmV-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozscreenshot 14:01:47 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)) 14:01:47 INFO - Unpacking /builds/slave/test/build/tests/mozbase/moztest 14:01:47 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-08KfGk-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/moztest 14:01:47 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)) 14:01:47 INFO - Unpacking /builds/slave/test/build/tests/mozbase/mozversion 14:01:47 INFO - Running setup.py (path:/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/pip-VAugwR-build/setup.py) egg_info for package from file:///builds/slave/test/build/tests/mozbase/mozversion 14:01:47 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)) 14:01:47 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)) 14:01:47 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)) 14:01:47 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)) 14:01:47 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.46->-r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 4)) 14:01:47 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.46->-r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 4)) 14:01:47 INFO - Downloading/unpacking blessings>=1.3 (from mozlog==3.0->-r /builds/slave/test/build/tests/config/mozbase_requirements.txt (line 10)) 14:01:47 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 14:01:47 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 14:01:47 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 14:01:47 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 14:01:47 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 14:01:47 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 14:01:50 INFO - Downloading blessings-1.5.1.tar.gz 14:01:50 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 14:01:50 INFO - Running setup.py (path:/builds/slave/test/build/venv/build/blessings/setup.py) egg_info for package blessings 14:01:50 INFO - Installing collected packages: blessings 14:01:50 INFO - Running setup.py install for blessings 14:01:50 INFO - Successfully installed blessings 14:01:50 INFO - Cleaning up... 14:01:50 INFO - Return code: 0 14:01:50 INFO - Done creating virtualenv /builds/slave/test/build/venv. 14:01:50 INFO - Getting output from command: ['/builds/slave/test/build/venv/bin/pip', 'freeze'] 14:01:50 INFO - Copy/paste: /builds/slave/test/build/venv/bin/pip freeze 14:01:50 INFO - Reading from file tmpfile_stdout 14:01:50 INFO - Current package versions: 14:01:50 INFO - blessings == 1.5.1 14:01:50 INFO - blobuploader == 1.2.4 14:01:50 INFO - docopt == 0.6.1 14:01:50 INFO - manifestparser == 1.1 14:01:50 INFO - mozInstall == 1.12 14:01:50 INFO - mozcrash == 0.16 14:01:50 INFO - mozdebug == 0.1 14:01:50 INFO - mozdevice == 0.46 14:01:50 INFO - mozfile == 1.2 14:01:50 INFO - mozhttpd == 0.7 14:01:50 INFO - mozinfo == 0.8 14:01:50 INFO - mozleak == 0.1 14:01:50 INFO - mozlog == 3.0 14:01:50 INFO - moznetwork == 0.27 14:01:50 INFO - mozprocess == 0.22 14:01:50 INFO - mozprofile == 0.27 14:01:50 INFO - mozrunner == 6.10 14:01:50 INFO - mozscreenshot == 0.1 14:01:50 INFO - mozsystemmonitor == 0.0 14:01:50 INFO - moztest == 0.7 14:01:50 INFO - mozversion == 1.4 14:01:50 INFO - psutil == 3.1.1 14:01:50 INFO - requests == 1.2.3 14:01:50 INFO - wsgiref == 0.1.2 14:01:50 INFO - Installing None into virtualenv /builds/slave/test/build/venv 14:01:50 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')]} 14:01:50 INFO - http://pypi.pvt.build.mozilla.org/pub matches http://pypi.pvt.build.mozilla.org 14:01:50 INFO - URL Candidate: http://pypi.pvt.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:50 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')]} 14:01:50 INFO - http://pypi.pub.build.mozilla.org/pub matches http://pypi.pub.build.mozilla.org 14:01:50 INFO - URL Candidate: http://pypi.pub.build.mozilla.org.proxxy1.srv.releng.scl3.mozilla.com/pub 14:01:50 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 0x105fbda30>, 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x10602a228>, 'level': 'warning'}, {'regex': <_sre.SRE_Pattern object at 0x7fd45358f8c0>, 'level': 'debug'}, {'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x105f729f0>, '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 0x105cd1cd8>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x105f3c990>, 'level': 'critical'}], 'cwd': '/builds/slave/test/build/tests/talos', 'env': {'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 'LOGNAME': 'cltbld', 'USER': 'cltbld', 'XPC_SERVICE_NAME': '0', 'HOME': '/Users/cltbld', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 'NO_EM_RESTART': '1', 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 'XPCOM_DEBUG_BREAK': 'warn', 'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 'VERSIONER_PYTHON_VERSION': '2.7', 'XPC_FLAGS': '0x0', 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 'MOZ_NO_REMOTE': '1', 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 'SHELL': '/bin/bash', 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0', 'PWD': '/builds/slave/test', 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 'MOZ_CRASHREPORTER_NO_REPORT': '1', 'PAGER': '/bin/cat'}}, attempt #1 14:01:50 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 14:01:50 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 14:01:50 INFO - Using env: {'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 14:01:50 INFO - 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 14:01:50 INFO - 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 14:01:50 INFO - 'HOME': '/Users/cltbld', 14:01:50 INFO - 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 14:01:50 INFO - 'LOGNAME': 'cltbld', 14:01:50 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 14:01:50 INFO - 'MOZ_NO_REMOTE': '1', 14:01:50 INFO - 'NO_EM_RESTART': '1', 14:01:50 INFO - 'PAGER': '/bin/cat', 14:01:50 INFO - 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 14:01:50 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 14:01:50 INFO - 'PWD': '/builds/slave/test', 14:01:50 INFO - 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 14:01:50 INFO - 'SHELL': '/bin/bash', 14:01:50 INFO - 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 14:01:50 INFO - 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', 14:01:50 INFO - 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 14:01:50 INFO - 'USER': 'cltbld', 14:01:50 INFO - 'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 14:01:50 INFO - 'VERSIONER_PYTHON_VERSION': '2.7', 14:01:50 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 14:01:50 INFO - 'XPC_FLAGS': '0x0', 14:01:50 INFO - 'XPC_SERVICE_NAME': '0', 14:01:50 INFO - '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0'} 14:01:51 INFO - Ignoring indexes: https://pypi.python.org/simple/ 14:01:51 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)) 14:01:51 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)) 14:01:51 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)) 14:01:51 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)) 14:01:51 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)) 14:01:51 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)) 14:01:51 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)) 14:01:51 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)) 14:01:51 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)) 14:01:51 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)) 14:01:51 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)) 14:01:51 INFO - Cleaning up... 14:01:51 INFO - Return code: 0 14:01:51 INFO - Running post-action listener: _resource_record_post_action 14:01:51 INFO - Running post-action listener: _start_resource_monitoring 14:01:51 INFO - Starting resource monitoring. 14:01:51 INFO - ##### 14:01:51 INFO - ##### Running install step. 14:01:51 INFO - ##### 14:01:51 INFO - Running pre-action listener: _resource_record_pre_action 14:01:51 INFO - Running main action method: install 14:01:51 INFO - Getting output from command: ['/builds/slave/test/build/venv/bin/pip', 'freeze'] 14:01:51 INFO - Copy/paste: /builds/slave/test/build/venv/bin/pip freeze 14:01:51 INFO - Reading from file tmpfile_stdout 14:01:51 INFO - Detecting whether we're running mozinstall >=1.0... 14:01:51 INFO - Getting output from command: ['/builds/slave/test/build/venv/bin/mozinstall', '-h'] 14:01:51 INFO - Copy/paste: /builds/slave/test/build/venv/bin/mozinstall -h 14:01:51 INFO - Reading from file tmpfile_stdout 14:01:51 INFO - Output received: 14:01:51 INFO - Usage: mozinstall [options] installer 14:01:51 INFO - Options: 14:01:51 INFO - -h, --help show this help message and exit 14:01:51 INFO - -d DEST, --destination=DEST 14:01:51 INFO - Directory to install application into. [default: 14:01:51 INFO - "/builds/slave/test"] 14:01:51 INFO - --app=APP Application being installed. [default: firefox] 14:01:51 INFO - mkdir: /builds/slave/test/build/application 14:01:51 INFO - Getting output from command: ['/builds/slave/test/build/venv/bin/mozinstall', '/builds/slave/test/build/firefox-44.0a1.en-US.mac.dmg', '--destination', '/builds/slave/test/build/application'] 14:01:51 INFO - Copy/paste: /builds/slave/test/build/venv/bin/mozinstall /builds/slave/test/build/firefox-44.0a1.en-US.mac.dmg --destination /builds/slave/test/build/application 14:02:27 INFO - Reading from file tmpfile_stdout 14:02:27 INFO - Output received: 14:02:27 INFO - /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox 14:02:27 INFO - Running post-action listener: _resource_record_post_action 14:02:27 INFO - ##### 14:02:27 INFO - ##### Running run-tests step. 14:02:27 INFO - ##### 14:02:27 INFO - Running pre-action listener: _resource_record_pre_action 14:02:27 INFO - Running main action method: run_tests 14:02:27 INFO - Running pre test command check_screen_resolution with 'bash -c screenresolution get && screenresolution list && system_profiler SPDisplaysDataType' 14:02:27 INFO - Running command: ['bash', '-c', 'screenresolution get && screenresolution list && system_profiler SPDisplaysDataType'] in /builds/slave/test/build 14:02:27 INFO - Copy/paste: bash -c "screenresolution get && screenresolution list && system_profiler SPDisplaysDataType" 14:02:27 INFO - 2015-10-23 14:02:27.618 screenresolution[1631:7514] starting screenresolution argv=screenresolution get 14:02:27 INFO - 2015-10-23 14:02:27.621 screenresolution[1631:7514] Display 0: 1600x1200x32@60 14:02:27 INFO - 2015-10-23 14:02:27.628 screenresolution[1632:7516] starting screenresolution argv=screenresolution list 14:02:27 INFO - Available Modes on Display 0 14:02:27 INFO - 1600x1200x32@60 1152x870x32@75 1280x1024x32@75 14:02:27 INFO - 1024x768x32@75 1024x768x32@70 1024x768x32@60 14:02:27 INFO - 800x600x32@75 800x600x32@60 640x480x32@75 14:02:27 INFO - 640x480x32@60 1280x1024x32@60 1280x960x32@60 14:02:27 INFO - 1280x960x32@75 1344x1008x32@60 Graphics/Displays: 14:02:27 INFO - Intel HD Graphics 3000: 14:02:27 INFO - Chipset Model: Intel HD Graphics 3000 14:02:27 INFO - Type: GPU 14:02:27 INFO - Bus: Built-In 14:02:27 INFO - VRAM (Total): 512 MB 14:02:27 INFO - VRAM (Dynamic, Max): 10 14:02:27 INFO - Vendor: Intel (0x8086) 14:02:27 INFO - Device ID: 0x0116 14:02:27 INFO - Revision ID: 0x0009 14:02:27 INFO - Displays: 14:02:27 INFO - Display: 14:02:27 INFO - Resolution: 1600 x 1200 @ 60 Hz 14:02:27 INFO - Pixel Depth: 32-Bit Color (ARGB8888) 14:02:27 INFO - Display Serial Number: 1600x1200 60 14:02:27 INFO - Main Display: Yes 14:02:27 INFO - Mirror: Off 14:02:27 INFO - Online: Yes 14:02:27 INFO - Rotation: Supported 14:02:27 INFO - Return code: 0 14:02:27 INFO - Running command: ['/builds/slave/test/build/venv/bin/python', '--version'] 14:02:27 INFO - Copy/paste: /builds/slave/test/build/venv/bin/python --version 14:02:27 INFO - Python 2.7.3 14:02:27 INFO - Return code: 0 14:02:27 INFO - grabbing minidump binary from tooltool 14:02:27 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')]} 14:02:27 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/macosx64/releng.manifest', '-o', '-c', '/builds/tooltool_cache'],), kwargs: {'error_list': [{'substr': 'command not found', 'level': 'error'}, {'regex': <_sre.SRE_Pattern object at 0x105f729f0>, '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 0x105cd1cd8>, 'level': 'critical'}, {'regex': <_sre.SRE_Pattern object at 0x105f3c990>, 'level': 'critical'}, {'substr': 'ERROR - ', 'level': 'error'}], 'cwd': '/builds/slave/test/build', 'privileged': False}, attempt #1 14:02:27 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/macosx64/releng.manifest', '-o', '-c', '/builds/tooltool_cache'] in /builds/slave/test/build 14:02:27 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/macosx64/releng.manifest -o -c /builds/tooltool_cache 14:02:27 INFO - INFO - File macosx64-minidump_stackwalk retrieved from local cache /builds/tooltool_cache 14:02:27 INFO - Return code: 0 14:02:27 INFO - Chmoding /builds/slave/test/build/macosx64-minidump_stackwalk to 0755 14:02:27 INFO - mkdir: /builds/slave/test/build/blobber_upload_dir 14:02:27 INFO - ENV: MOZ_UPLOAD_DIR is now /builds/slave/test/build/blobber_upload_dir 14:02:27 INFO - ENV: MINIDUMP_STACKWALK is now /builds/slave/test/build/macosx64-minidump_stackwalk 14:02:27 INFO - ENV: MINIDUMP_SAVE_PATH is now /builds/slave/test/build/blobber_upload_dir 14:02:27 INFO - Running command: ['/builds/slave/test/build/venv/bin/python', '/builds/slave/test/build/tests/talos/talos/run_tests.py', '--debug', '--branchName', 'Fx-Team', '--suite', 'other', '--executablePath', '/builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox', '--symbolsPath', 'https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.crashreporter-symbols.zip', '--title', 't-yosemite-r5-0016', '--webServer', 'localhost'] in /builds/slave/test/build 14:02:27 INFO - Copy/paste: /builds/slave/test/build/venv/bin/python /builds/slave/test/build/tests/talos/talos/run_tests.py --debug --branchName Fx-Team --suite other --executablePath /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox --symbolsPath https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.crashreporter-symbols.zip --title t-yosemite-r5-0016 --webServer localhost 14:02:27 INFO - Using env: {'Apple_PubSub_Socket_Render': '/private/tmp/com.apple.launchd.hzmkYpjbIV/Render', 14:02:27 INFO - 'GIT_SHARE_BASE_DIR': '/builds/git-shared', 14:02:27 INFO - 'HG_SHARE_BASE_DIR': '/builds/hg-shared', 14:02:27 INFO - 'HOME': '/Users/cltbld', 14:02:27 INFO - 'IDLEIZER_DISABLE_SHUTDOWN': 'true', 14:02:27 INFO - 'LOGNAME': 'cltbld', 14:02:27 INFO - 'MINIDUMP_SAVE_PATH': '/builds/slave/test/build/blobber_upload_dir', 14:02:27 INFO - 'MINIDUMP_STACKWALK': '/builds/slave/test/build/macosx64-minidump_stackwalk', 14:02:27 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1', 14:02:27 INFO - 'MOZ_NO_REMOTE': '1', 14:02:27 INFO - 'MOZ_UPLOAD_DIR': '/builds/slave/test/build/blobber_upload_dir', 14:02:27 INFO - 'NO_EM_RESTART': '1', 14:02:27 INFO - 'PAGER': '/bin/cat', 14:02:27 INFO - 'PATH': '/builds/slave/test/build/venv/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11', 14:02:27 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json', 14:02:27 INFO - 'PWD': '/builds/slave/test', 14:02:27 INFO - 'PYTHONPATH': '/builds/slave/test/build/tests/talos', 14:02:27 INFO - 'RUNNER_CONFIG_CMD': '/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg', 14:02:27 INFO - 'SHELL': '/bin/bash', 14:02:27 INFO - 'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners', 14:02:28 INFO - 'TMPDIR': '/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/', 14:02:28 INFO - 'TWISTD_LOG_PATH': '/builds/slave/twistd.log', 14:02:28 INFO - 'USER': 'cltbld', 14:02:28 INFO - 'VERSIONER_PYTHON_PREFER_32_BIT': 'no', 14:02:28 INFO - 'VERSIONER_PYTHON_VERSION': '2.7', 14:02:28 INFO - 'XPCOM_DEBUG_BREAK': 'warn', 14:02:28 INFO - 'XPC_FLAGS': '0x0', 14:02:28 INFO - 'XPC_SERVICE_NAME': '0', 14:02:28 INFO - '__CF_USER_TEXT_ENCODING': '0x1C:0x0:0x0'} 14:02:28 INFO - Calling ['/builds/slave/test/build/venv/bin/python', '/builds/slave/test/build/tests/talos/talos/run_tests.py', '--debug', '--branchName', 'Fx-Team', '--suite', 'other', '--executablePath', '/builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox', '--symbolsPath', 'https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.crashreporter-symbols.zip', '--title', 't-yosemite-r5-0016', '--webServer', 'localhost'] with output_timeout 3600 14:02:28 INFO - mozversion INFO | application_buildid: 20151023121232 14:02:28 INFO - mozversion INFO | application_changeset: ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc 14:02:28 INFO - mozversion INFO | application_display_name: Nightly 14:02:28 INFO - mozversion INFO | application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384} 14:02:28 INFO - mozversion INFO | application_name: Firefox 14:02:28 INFO - mozversion INFO | application_remotingname: firefox 14:02:28 INFO - mozversion INFO | application_repository: https://hg.mozilla.org/integration/fx-team 14:02:28 INFO - mozversion INFO | application_vendor: Mozilla 14:02:28 INFO - mozversion INFO | application_version: 44.0a1 14:02:28 INFO - mozversion INFO | platform_buildid: 20151023121232 14:02:28 INFO - mozversion INFO | platform_changeset: ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc 14:02:28 INFO - mozversion INFO | platform_repository: https://hg.mozilla.org/integration/fx-team 14:02:28 INFO - mozversion INFO | platform_version: 44.0a1 14:02:28 INFO - 2015-10-23 14:02:28,326 DEBUG : using testdate: 1445634148 14:02:28 INFO - 2015-10-23 14:02:28,326 DEBUG : actual date: 1445634148 14:02:28 INFO - 2015-10-23 14:02:28,337 INFO : starting webserver on 'localhost:49269' 14:02:28 INFO - 2015-10-23 14:02:28,338 INFO : Starting test suite t-yosemite-r5-0016 14:02:28 INFO - 2015-10-23 14:02:28,338 INFO : Starting test a11yr 14:02:28 INFO - 2015-10-23 14:02:28,338 DEBUG : operating with platform_type : mac_ 14:02:28 INFO - 2015-10-23 14:02:28,339 INFO : Initialising browser for a11yr test... 14:02:28 INFO - 2015-10-23 14:02:28,353 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpjDgKme/profile http://localhost:49269/getInfo.html 14:02:31 INFO - 2015-10-23 14:02:31,192 DEBUG : BROWSER_OUTPUT: __metrics Screen width/height:1600/1200 14:02:31 INFO - 2015-10-23 14:02:31,193 DEBUG : BROWSER_OUTPUT: colorDepth:24 14:02:31 INFO - 2015-10-23 14:02:31,193 DEBUG : BROWSER_OUTPUT: Browser inner width/height: 1024/689 14:02:31 INFO - 2015-10-23 14:02:31,193 DEBUG : BROWSER_OUTPUT: __metrics 14:02:31 INFO - 2015-10-23 14:02:31,210 DEBUG : BROWSER_OUTPUT: JavaScript error: resource:///modules/WebappManager.jsm, line 48: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver] 14:02:31 INFO - 2015-10-23 14:02:31,940 INFO : Browser initialized. 14:02:31 INFO - 2015-10-23 14:02:31,940 INFO : Running cycle 1/1 for a11yr test... 14:02:31 INFO - 2015-10-23 14:02:31,940 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpjDgKme/profile -tp file:/builds/slave/test/build/tests/talos/talos/tests/a11y/a11y.manifest.develop -tpchrome -tpmozafterpaint -tpnoisy -tpcycles 1 -tppagecycles 25 14:02:43 INFO - 2015-10-23 14:02:43,867 DEBUG : BROWSER_OUTPUT: RSS: Main: 222507008 14:02:43 INFO - 2015-10-23 14:02:43,867 DEBUG : BROWSER_OUTPUT: 14:02:45 INFO - 2015-10-23 14:02:45,038 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) 14:02:45 INFO - 2015-10-23 14:02:45,647 DEBUG : BROWSER_OUTPUT: RSS: Main: 274829312 14:02:45 INFO - 2015-10-23 14:02:45,647 DEBUG : BROWSER_OUTPUT: 14:02:46 INFO - 2015-10-23 14:02:46,866 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) 14:02:47 INFO - 2015-10-23 14:02:47,534 DEBUG : BROWSER_OUTPUT: RSS: Main: 289869824 14:02:47 INFO - 2015-10-23 14:02:47,534 DEBUG : BROWSER_OUTPUT: 14:02:48 INFO - 2015-10-23 14:02:48,643 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) 14:02:49 INFO - 2015-10-23 14:02:49,328 DEBUG : BROWSER_OUTPUT: RSS: Main: 289505280 14:02:49 INFO - 2015-10-23 14:02:49,328 DEBUG : BROWSER_OUTPUT: 14:02:50 INFO - 2015-10-23 14:02:50,550 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) 14:02:51 INFO - 2015-10-23 14:02:51,216 DEBUG : BROWSER_OUTPUT: RSS: Main: 291807232 14:02:51 INFO - 2015-10-23 14:02:51,216 DEBUG : BROWSER_OUTPUT: 14:02:52 INFO - 2015-10-23 14:02:52,420 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) 14:02:53 INFO - 2015-10-23 14:02:53,091 DEBUG : BROWSER_OUTPUT: RSS: Main: 290492416 14:02:53 INFO - 2015-10-23 14:02:53,091 DEBUG : BROWSER_OUTPUT: 14:02:54 INFO - 2015-10-23 14:02:54,319 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) 14:02:54 INFO - 2015-10-23 14:02:54,999 DEBUG : BROWSER_OUTPUT: RSS: Main: 291495936 14:02:54 INFO - 2015-10-23 14:02:54,999 DEBUG : BROWSER_OUTPUT: 14:02:56 INFO - 2015-10-23 14:02:56,222 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) 14:02:56 INFO - 2015-10-23 14:02:56,892 DEBUG : BROWSER_OUTPUT: RSS: Main: 291909632 14:02:56 INFO - 2015-10-23 14:02:56,892 DEBUG : BROWSER_OUTPUT: 14:02:58 INFO - 2015-10-23 14:02:58,120 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) 14:02:58 INFO - 2015-10-23 14:02:58,791 DEBUG : BROWSER_OUTPUT: RSS: Main: 293531648 14:02:58 INFO - 2015-10-23 14:02:58,791 DEBUG : BROWSER_OUTPUT: 14:03:00 INFO - 2015-10-23 14:03:00,047 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) 14:03:00 INFO - 2015-10-23 14:03:00,727 DEBUG : BROWSER_OUTPUT: RSS: Main: 292601856 14:03:00 INFO - 2015-10-23 14:03:00,727 DEBUG : BROWSER_OUTPUT: 14:03:01 INFO - 2015-10-23 14:03:01,921 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) 14:03:02 INFO - 2015-10-23 14:03:02,603 DEBUG : BROWSER_OUTPUT: RSS: Main: 294023168 14:03:02 INFO - 2015-10-23 14:03:02,603 DEBUG : BROWSER_OUTPUT: 14:03:03 INFO - 2015-10-23 14:03:03,833 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) 14:03:04 INFO - 2015-10-23 14:03:04,516 DEBUG : BROWSER_OUTPUT: RSS: Main: 293470208 14:03:04 INFO - 2015-10-23 14:03:04,516 DEBUG : BROWSER_OUTPUT: 14:03:05 INFO - 2015-10-23 14:03:05,744 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) 14:03:06 INFO - 2015-10-23 14:03:06,428 DEBUG : BROWSER_OUTPUT: RSS: Main: 293027840 14:03:06 INFO - 2015-10-23 14:03:06,429 DEBUG : BROWSER_OUTPUT: 14:03:07 INFO - 2015-10-23 14:03:07,562 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) 14:03:08 INFO - 2015-10-23 14:03:08,244 DEBUG : BROWSER_OUTPUT: RSS: Main: 292438016 14:03:08 INFO - 2015-10-23 14:03:08,244 DEBUG : BROWSER_OUTPUT: 14:03:09 INFO - 2015-10-23 14:03:09,500 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) 14:03:10 INFO - 2015-10-23 14:03:10,181 DEBUG : BROWSER_OUTPUT: RSS: Main: 293343232 14:03:10 INFO - 2015-10-23 14:03:10,181 DEBUG : BROWSER_OUTPUT: 14:03:11 INFO - 2015-10-23 14:03:11,311 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) 14:03:11 INFO - 2015-10-23 14:03:11,992 DEBUG : BROWSER_OUTPUT: RSS: Main: 293916672 14:03:11 INFO - 2015-10-23 14:03:11,992 DEBUG : BROWSER_OUTPUT: 14:03:13 INFO - 2015-10-23 14:03:13,236 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) 14:03:13 INFO - 2015-10-23 14:03:13,916 DEBUG : BROWSER_OUTPUT: RSS: Main: 294408192 14:03:13 INFO - 2015-10-23 14:03:13,916 DEBUG : BROWSER_OUTPUT: 14:03:15 INFO - 2015-10-23 14:03:15,132 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) 14:03:15 INFO - 2015-10-23 14:03:15,813 DEBUG : BROWSER_OUTPUT: RSS: Main: 293740544 14:03:15 INFO - 2015-10-23 14:03:15,813 DEBUG : BROWSER_OUTPUT: 14:03:17 INFO - 2015-10-23 14:03:17,017 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) 14:03:17 INFO - 2015-10-23 14:03:17,693 DEBUG : BROWSER_OUTPUT: RSS: Main: 294682624 14:03:17 INFO - 2015-10-23 14:03:17,694 DEBUG : BROWSER_OUTPUT: 14:03:18 INFO - 2015-10-23 14:03:18,920 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) 14:03:19 INFO - 2015-10-23 14:03:19,601 DEBUG : BROWSER_OUTPUT: RSS: Main: 294768640 14:03:19 INFO - 2015-10-23 14:03:19,601 DEBUG : BROWSER_OUTPUT: 14:03:20 INFO - 2015-10-23 14:03:20,831 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) 14:03:21 INFO - 2015-10-23 14:03:21,517 DEBUG : BROWSER_OUTPUT: RSS: Main: 293052416 14:03:21 INFO - 2015-10-23 14:03:21,517 DEBUG : BROWSER_OUTPUT: 14:03:22 INFO - 2015-10-23 14:03:22,741 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) 14:03:23 INFO - 2015-10-23 14:03:23,420 DEBUG : BROWSER_OUTPUT: RSS: Main: 292642816 14:03:23 INFO - 2015-10-23 14:03:23,420 DEBUG : BROWSER_OUTPUT: 14:03:24 INFO - 2015-10-23 14:03:24,647 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) 14:03:25 INFO - 2015-10-23 14:03:25,330 DEBUG : BROWSER_OUTPUT: RSS: Main: 293507072 14:03:25 INFO - 2015-10-23 14:03:25,330 DEBUG : BROWSER_OUTPUT: 14:03:26 INFO - 2015-10-23 14:03:26,518 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) 14:03:27 INFO - 2015-10-23 14:03:27,198 DEBUG : BROWSER_OUTPUT: RSS: Main: 295960576 14:03:27 INFO - 2015-10-23 14:03:27,199 DEBUG : BROWSER_OUTPUT: 14:03:28 INFO - 2015-10-23 14:03:28,423 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) 14:03:29 INFO - 2015-10-23 14:03:29,097 DEBUG : BROWSER_OUTPUT: RSS: Main: 295579648 14:03:29 INFO - 2015-10-23 14:03:29,097 DEBUG : BROWSER_OUTPUT: 14:03:30 INFO - 2015-10-23 14:03:30,324 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) 14:03:31 INFO - 2015-10-23 14:03:31,006 DEBUG : BROWSER_OUTPUT: RSS: Main: 296062976 14:03:31 INFO - 2015-10-23 14:03:31,006 DEBUG : BROWSER_OUTPUT: 14:03:31 INFO - 2015-10-23 14:03:31,775 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) 14:03:32 INFO - 2015-10-23 14:03:32,347 DEBUG : BROWSER_OUTPUT: RSS: Main: 288894976 14:03:32 INFO - 2015-10-23 14:03:32,348 DEBUG : BROWSER_OUTPUT: 14:03:33 INFO - 2015-10-23 14:03:33,043 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) 14:03:33 INFO - 2015-10-23 14:03:33,627 DEBUG : BROWSER_OUTPUT: RSS: Main: 300789760 14:03:33 INFO - 2015-10-23 14:03:33,628 DEBUG : BROWSER_OUTPUT: 14:03:33 INFO - 2015-10-23 14:03:33,945 DEBUG : BROWSER_OUTPUT: 1445634213944 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] 14:03:34 INFO - 2015-10-23 14:03:34,345 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) 14:03:34 INFO - 2015-10-23 14:03:34,947 DEBUG : BROWSER_OUTPUT: RSS: Main: 305582080 14:03:34 INFO - 2015-10-23 14:03:34,947 DEBUG : BROWSER_OUTPUT: 14:03:35 INFO - 2015-10-23 14:03:35,651 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) 14:03:36 INFO - 2015-10-23 14:03:36,243 DEBUG : BROWSER_OUTPUT: RSS: Main: 305176576 14:03:36 INFO - 2015-10-23 14:03:36,243 DEBUG : BROWSER_OUTPUT: 14:03:36 INFO - 2015-10-23 14:03:36,950 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) 14:03:37 INFO - 2015-10-23 14:03:37,549 DEBUG : BROWSER_OUTPUT: RSS: Main: 305651712 14:03:37 INFO - 2015-10-23 14:03:37,549 DEBUG : BROWSER_OUTPUT: 14:03:38 INFO - 2015-10-23 14:03:38,252 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) 14:03:38 INFO - 2015-10-23 14:03:38,845 DEBUG : BROWSER_OUTPUT: RSS: Main: 304496640 14:03:38 INFO - 2015-10-23 14:03:38,845 DEBUG : BROWSER_OUTPUT: 14:03:39 INFO - 2015-10-23 14:03:39,550 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) 14:03:40 INFO - 2015-10-23 14:03:40,148 DEBUG : BROWSER_OUTPUT: RSS: Main: 305360896 14:03:40 INFO - 2015-10-23 14:03:40,148 DEBUG : BROWSER_OUTPUT: 14:03:40 INFO - 2015-10-23 14:03:40,849 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) 14:03:41 INFO - 2015-10-23 14:03:41,452 DEBUG : BROWSER_OUTPUT: RSS: Main: 305520640 14:03:41 INFO - 2015-10-23 14:03:41,452 DEBUG : BROWSER_OUTPUT: 14:03:42 INFO - 2015-10-23 14:03:42,153 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) 14:03:42 INFO - 2015-10-23 14:03:42,746 DEBUG : BROWSER_OUTPUT: RSS: Main: 304451584 14:03:42 INFO - 2015-10-23 14:03:42,746 DEBUG : BROWSER_OUTPUT: 14:03:43 INFO - 2015-10-23 14:03:43,449 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) 14:03:44 INFO - 2015-10-23 14:03:44,040 DEBUG : BROWSER_OUTPUT: RSS: Main: 305033216 14:03:44 INFO - 2015-10-23 14:03:44,040 DEBUG : BROWSER_OUTPUT: 14:03:44 INFO - 2015-10-23 14:03:44,747 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) 14:03:45 INFO - 2015-10-23 14:03:45,339 DEBUG : BROWSER_OUTPUT: RSS: Main: 300081152 14:03:45 INFO - 2015-10-23 14:03:45,339 DEBUG : BROWSER_OUTPUT: 14:03:46 INFO - 2015-10-23 14:03:46,049 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) 14:03:46 INFO - 2015-10-23 14:03:46,650 DEBUG : BROWSER_OUTPUT: RSS: Main: 299024384 14:03:46 INFO - 2015-10-23 14:03:46,650 DEBUG : BROWSER_OUTPUT: 14:03:47 INFO - 2015-10-23 14:03:47,354 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) 14:03:47 INFO - 2015-10-23 14:03:47,945 DEBUG : BROWSER_OUTPUT: RSS: Main: 298946560 14:03:47 INFO - 2015-10-23 14:03:47,945 DEBUG : BROWSER_OUTPUT: 14:03:48 INFO - 2015-10-23 14:03:48,650 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) 14:03:49 INFO - 2015-10-23 14:03:49,242 DEBUG : BROWSER_OUTPUT: RSS: Main: 299048960 14:03:49 INFO - 2015-10-23 14:03:49,242 DEBUG : BROWSER_OUTPUT: 14:03:49 INFO - 2015-10-23 14:03:49,949 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) 14:03:50 INFO - 2015-10-23 14:03:50,548 DEBUG : BROWSER_OUTPUT: RSS: Main: 299081728 14:03:50 INFO - 2015-10-23 14:03:50,548 DEBUG : BROWSER_OUTPUT: 14:03:51 INFO - 2015-10-23 14:03:51,253 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) 14:03:51 INFO - 2015-10-23 14:03:51,845 DEBUG : BROWSER_OUTPUT: RSS: Main: 299163648 14:03:51 INFO - 2015-10-23 14:03:51,845 DEBUG : BROWSER_OUTPUT: 14:03:52 INFO - 2015-10-23 14:03:52,555 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) 14:03:53 INFO - 2015-10-23 14:03:53,156 DEBUG : BROWSER_OUTPUT: RSS: Main: 299122688 14:03:53 INFO - 2015-10-23 14:03:53,156 DEBUG : BROWSER_OUTPUT: 14:03:53 INFO - 2015-10-23 14:03:53,829 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) 14:03:54 INFO - 2015-10-23 14:03:54,424 DEBUG : BROWSER_OUTPUT: RSS: Main: 299151360 14:03:54 INFO - 2015-10-23 14:03:54,424 DEBUG : BROWSER_OUTPUT: 14:03:55 INFO - 2015-10-23 14:03:55,099 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) 14:03:55 INFO - 2015-10-23 14:03:55,694 DEBUG : BROWSER_OUTPUT: RSS: Main: 297590784 14:03:55 INFO - 2015-10-23 14:03:55,695 DEBUG : BROWSER_OUTPUT: 14:03:56 INFO - 2015-10-23 14:03:56,401 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) 14:03:56 INFO - 2015-10-23 14:03:56,993 DEBUG : BROWSER_OUTPUT: RSS: Main: 296464384 14:03:56 INFO - 2015-10-23 14:03:56,994 DEBUG : BROWSER_OUTPUT: 14:03:57 INFO - 2015-10-23 14:03:57,716 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) 14:03:58 INFO - 2015-10-23 14:03:58,317 DEBUG : BROWSER_OUTPUT: RSS: Main: 296509440 14:03:58 INFO - 2015-10-23 14:03:58,318 DEBUG : BROWSER_OUTPUT: 14:03:59 INFO - 2015-10-23 14:03:59,017 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) 14:03:59 INFO - 2015-10-23 14:03:59,612 DEBUG : BROWSER_OUTPUT: RSS: Main: 296869888 14:03:59 INFO - 2015-10-23 14:03:59,612 DEBUG : BROWSER_OUTPUT: 14:04:00 INFO - 2015-10-23 14:04:00,319 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) 14:04:00 INFO - 2015-10-23 14:04:00,910 DEBUG : BROWSER_OUTPUT: RSS: Main: 296693760 14:04:00 INFO - 2015-10-23 14:04:00,910 DEBUG : BROWSER_OUTPUT: 14:04:01 INFO - 2015-10-23 14:04:01,618 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) 14:04:02 INFO - 2015-10-23 14:04:02,210 DEBUG : BROWSER_OUTPUT: RSS: Main: 296701952 14:04:02 INFO - 2015-10-23 14:04:02,210 DEBUG : BROWSER_OUTPUT: 14:04:02 INFO - 2015-10-23 14:04:02,917 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) 14:04:03 INFO - 2015-10-23 14:04:03,167 DEBUG : BROWSER_OUTPUT: RSS: Main: 301113344 14:04:03 INFO - 2015-10-23 14:04:03,167 DEBUG : BROWSER_OUTPUT: 14:04:03 INFO - 2015-10-23 14:04:03,167 DEBUG : BROWSER_OUTPUT: __start_tp_report 14:04:03 INFO - 2015-10-23 14:04:03,167 DEBUG : BROWSER_OUTPUT: _x_x_mozilla_page_load 14:04:03 INFO - 2015-10-23 14:04:03,167 DEBUG : BROWSER_OUTPUT: _x_x_mozilla_page_load_details 14:04:03 INFO - 2015-10-23 14:04:03,168 DEBUG : BROWSER_OUTPUT: |i|pagename|runs| 14:04:03 INFO - 2015-10-23 14:04:03,168 DEBUG : BROWSER_OUTPUT: |0;dhtml.html;1109;1141;1059;1146;1144;1145;1142;1147;1181;1147;1155;1153;1063;1183;1062;1184;1156;1143;1148;1161;1149;1150;1143;1153;1155 14:04:03 INFO - 2015-10-23 14:04:03,169 DEBUG : BROWSER_OUTPUT: |1;tablemutation.html;264;262;267;258;259;260;258;259;259;257;258;259;260;259;259;259;261;261;259;259;260;259;260;259;258 14:04:03 INFO - 2015-10-23 14:04:03,169 DEBUG : BROWSER_OUTPUT: __end_tp_report 14:04:03 INFO - 2015-10-23 14:04:03,169 DEBUG : BROWSER_OUTPUT: __start_cc_report 14:04:03 INFO - 2015-10-23 14:04:03,169 DEBUG : BROWSER_OUTPUT: _x_x_mozilla_cycle_collect,6444 14:04:03 INFO - 2015-10-23 14:04:03,170 DEBUG : BROWSER_OUTPUT: __end_cc_report 14:04:03 INFO - 2015-10-23 14:04:03,170 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634243166__endTimestamp 14:04:03 INFO - 2015-10-23 14:04:03,170 DEBUG : BROWSER_OUTPUT: 14:04:03 INFO - 2015-10-23 14:04:03,170 DEBUG : BROWSER_OUTPUT: ------- Summary: start ------- 14:04:03 INFO - 2015-10-23 14:04:03,170 DEBUG : BROWSER_OUTPUT: Number of tests: 2 14:04:03 INFO - 2015-10-23 14:04:03,170 DEBUG : BROWSER_OUTPUT: 14:04:03 INFO - 2015-10-23 14:04:03,170 DEBUG : BROWSER_OUTPUT: [#0] dhtml.html Cycles:25 Average:1140.76 Median:1147.00 stddev:33.49 (2.9%) stddev-sans-first:33.53 14:04:03 INFO - 2015-10-23 14:04:03,170 DEBUG : BROWSER_OUTPUT: Values: 1109.0 1141.0 1059.0 1146.0 1144.0 1145.0 1142.0 1147.0 1181.0 1147.0 1155.0 1153.0 1063.0 1183.0 1062.0 1184.0 1156.0 1143.0 1148.0 1161.0 1149.0 1150.0 1143.0 1153.0 1155.0 14:04:03 INFO - 2015-10-23 14:04:03,171 DEBUG : BROWSER_OUTPUT: 14:04:03 INFO - 2015-10-23 14:04:03,171 DEBUG : BROWSER_OUTPUT: [#1] tablemutation.html Cycles:25 Average:259.72 Median:259.00 stddev:2.09 (0.8%) stddev-sans-first:1.93 14:04:03 INFO - 2015-10-23 14:04:03,171 DEBUG : BROWSER_OUTPUT: Values: 264.0 262.0 267.0 258.0 259.0 260.0 258.0 259.0 259.0 257.0 258.0 259.0 260.0 259.0 259.0 259.0 261.0 261.0 259.0 259.0 260.0 259.0 260.0 259.0 258.0 14:04:03 INFO - 2015-10-23 14:04:03,171 DEBUG : BROWSER_OUTPUT: -------- Summary: end -------- 14:04:03 INFO - 2015-10-23 14:04:03,171 DEBUG : BROWSER_OUTPUT: 14:04:03 INFO - 2015-10-23 14:04:03,677 INFO : Browser exited with error code: 0 14:04:03 INFO - 2015-10-23 14:04:03,698 INFO : Completed test a11yr (00:01:35) 14:04:03 INFO - 2015-10-23 14:04:03,698 INFO : Starting test ts_paint 14:04:03 INFO - 2015-10-23 14:04:03,698 DEBUG : operating with platform_type : mac_ 14:04:03 INFO - 2015-10-23 14:04:03,698 INFO : Initialising browser for ts_paint test... 14:04:03 INFO - 2015-10-23 14:04:03,712 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/getInfo.html 14:04:05 INFO - 2015-10-23 14:04:05,880 DEBUG : BROWSER_OUTPUT: __metrics Screen width/height:1600/1200 14:04:05 INFO - 2015-10-23 14:04:05,880 DEBUG : BROWSER_OUTPUT: colorDepth:24 14:04:05 INFO - 2015-10-23 14:04:05,880 DEBUG : BROWSER_OUTPUT: Browser inner width/height: 1024/689 14:04:05 INFO - 2015-10-23 14:04:05,881 DEBUG : BROWSER_OUTPUT: __metrics 14:04:05 INFO - 2015-10-23 14:04:05,888 DEBUG : BROWSER_OUTPUT: JavaScript error: resource:///modules/WebappManager.jsm, line 48: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver] 14:04:06 INFO - 2015-10-23 14:04:06,160 DEBUG : BROWSER_OUTPUT: console.error: 14:04:06 INFO - 2015-10-23 14:04:06,160 DEBUG : BROWSER_OUTPUT: Message: [Exception... "Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [mozIStorageAsyncStatement.executeAsync]" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "JS frame :: resource://gre/modules/Sqlite.jsm :: ConnectionData.prototype<._executeStatement :: line 758" data: no] 14:04:06 INFO - 2015-10-23 14:04:06,160 DEBUG : BROWSER_OUTPUT: Stack: 14:04:06 INFO - 2015-10-23 14:04:06,160 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<._executeStatement@resource://gre/modules/Sqlite.jsm:758:19 14:04:06 INFO - 2015-10-23 14:04:06,160 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<.executeCached/<@resource://gre/modules/Sqlite.jsm:493:9 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<.executeCached@resource://gre/modules/Sqlite.jsm:491:1 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<.executeBeforeShutdown/loggedDb<.executeCached.value<@resource://gre/modules/Sqlite.jsm:368:51 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:314:40 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: TaskImpl@resource://gre/modules/Task.jsm:275:3 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:249:14 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: setAncestorsLastModified<@resource://gre/modules/Bookmarks.jsm:1347:9 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:314:40 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: TaskImpl@resource://gre/modules/Task.jsm:275:3 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:249:14 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: transaction@resource://gre/modules/Bookmarks.jsm:808:13 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:314:40 14:04:06 INFO - 2015-10-23 14:04:06,161 DEBUG : BROWSER_OUTPUT: Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:934:23 14:04:06 INFO - 2015-10-23 14:04:06,162 DEBUG : BROWSER_OUTPUT: this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:813:7 14:04:06 INFO - 2015-10-23 14:04:06,162 DEBUG : BROWSER_OUTPUT: Promise*this.PromiseWalker.scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:744:11 14:04:06 INFO - 2015-10-23 14:04:06,162 DEBUG : BROWSER_OUTPUT: this.PromiseWalker.schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:776:7 14:04:06 INFO - 2015-10-23 14:04:06,162 DEBUG : BROWSER_OUTPUT: this.PromiseWalker.completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:711:7 14:04:06 INFO - 2015-10-23 14:04:06,162 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:319:13 14:04:06 INFO - 2015-10-23 14:04:06,162 DEBUG : BROWSER_OUTPUT: Spinner.prototype.observe@resource://gre/modules/AsyncShutdown.jsm:523:9 14:04:06 INFO - 2015-10-23 14:04:06,162 DEBUG : BROWSER_OUTPUT: 14:04:06 INFO - 2015-10-23 14:04:06,607 INFO : Browser initialized. 14:04:06 INFO - 2015-10-23 14:04:06,608 INFO : Running cycle 1/20 for ts_paint test... 14:04:06 INFO - 2015-10-23 14:04:06,608 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:08 INFO - 2015-10-23 14:04:08,330 DEBUG : BROWSER_OUTPUT: __start_report1714__end_report 14:04:08 INFO - 2015-10-23 14:04:08,330 DEBUG : BROWSER_OUTPUT: 14:04:08 INFO - 2015-10-23 14:04:08,347 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634248338__endTimestamp 14:04:08 INFO - 2015-10-23 14:04:08,960 INFO : Browser exited with error code: 0 14:04:08 INFO - 2015-10-23 14:04:08,962 INFO : Running cycle 2/20 for ts_paint test... 14:04:08 INFO - 2015-10-23 14:04:08,962 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:10 INFO - 2015-10-23 14:04:10,232 DEBUG : BROWSER_OUTPUT: __start_report1264__end_report 14:04:10 INFO - 2015-10-23 14:04:10,232 DEBUG : BROWSER_OUTPUT: 14:04:10 INFO - 2015-10-23 14:04:10,232 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634250230__endTimestamp 14:04:10 INFO - 2015-10-23 14:04:10,852 INFO : Browser exited with error code: 0 14:04:10 INFO - 2015-10-23 14:04:10,853 INFO : Running cycle 3/20 for ts_paint test... 14:04:10 INFO - 2015-10-23 14:04:10,854 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:12 INFO - 2015-10-23 14:04:12,132 DEBUG : BROWSER_OUTPUT: __start_report1270__end_report 14:04:12 INFO - 2015-10-23 14:04:12,132 DEBUG : BROWSER_OUTPUT: 14:04:12 INFO - 2015-10-23 14:04:12,149 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634252142__endTimestamp 14:04:12 INFO - 2015-10-23 14:04:12,818 INFO : Browser exited with error code: 0 14:04:12 INFO - 2015-10-23 14:04:12,819 INFO : Running cycle 4/20 for ts_paint test... 14:04:12 INFO - 2015-10-23 14:04:12,819 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:14 INFO - 2015-10-23 14:04:14,083 DEBUG : BROWSER_OUTPUT: __start_report1260__end_report 14:04:14 INFO - 2015-10-23 14:04:14,083 DEBUG : BROWSER_OUTPUT: 14:04:14 INFO - 2015-10-23 14:04:14,099 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634254096__endTimestamp 14:04:14 INFO - 2015-10-23 14:04:14,817 INFO : Browser exited with error code: 0 14:04:14 INFO - 2015-10-23 14:04:14,818 INFO : Running cycle 5/20 for ts_paint test... 14:04:14 INFO - 2015-10-23 14:04:14,819 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:16 INFO - 2015-10-23 14:04:16,082 DEBUG : BROWSER_OUTPUT: __start_report1261__end_report 14:04:16 INFO - 2015-10-23 14:04:16,083 DEBUG : BROWSER_OUTPUT: 14:04:16 INFO - 2015-10-23 14:04:16,100 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634256096__endTimestamp 14:04:16 INFO - 2015-10-23 14:04:16,858 INFO : Browser exited with error code: 0 14:04:16 INFO - 2015-10-23 14:04:16,860 INFO : Running cycle 6/20 for ts_paint test... 14:04:16 INFO - 2015-10-23 14:04:16,860 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:18 INFO - 2015-10-23 14:04:18,129 DEBUG : BROWSER_OUTPUT: __start_report1267__end_report 14:04:18 INFO - 2015-10-23 14:04:18,129 DEBUG : BROWSER_OUTPUT: 14:04:18 INFO - 2015-10-23 14:04:18,133 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634258132__endTimestamp 14:04:18 INFO - 2015-10-23 14:04:18,859 INFO : Browser exited with error code: 0 14:04:18 INFO - 2015-10-23 14:04:18,861 INFO : Running cycle 7/20 for ts_paint test... 14:04:18 INFO - 2015-10-23 14:04:18,861 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:20 INFO - 2015-10-23 14:04:20,135 DEBUG : BROWSER_OUTPUT: __start_report1270__end_report 14:04:20 INFO - 2015-10-23 14:04:20,135 DEBUG : BROWSER_OUTPUT: 14:04:20 INFO - 2015-10-23 14:04:20,143 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634260142__endTimestamp 14:04:20 INFO - 2015-10-23 14:04:20,890 INFO : Browser exited with error code: 0 14:04:20 INFO - 2015-10-23 14:04:20,891 INFO : Running cycle 8/20 for ts_paint test... 14:04:20 INFO - 2015-10-23 14:04:20,891 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:22 INFO - 2015-10-23 14:04:22,151 DEBUG : BROWSER_OUTPUT: __start_report1255__end_report 14:04:22 INFO - 2015-10-23 14:04:22,151 DEBUG : BROWSER_OUTPUT: 14:04:22 INFO - 2015-10-23 14:04:22,169 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634262162__endTimestamp 14:04:22 INFO - 2015-10-23 14:04:22,915 INFO : Browser exited with error code: 0 14:04:22 INFO - 2015-10-23 14:04:22,916 INFO : Running cycle 9/20 for ts_paint test... 14:04:22 INFO - 2015-10-23 14:04:22,916 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:24 INFO - 2015-10-23 14:04:24,185 DEBUG : BROWSER_OUTPUT: __start_report1264__end_report 14:04:24 INFO - 2015-10-23 14:04:24,185 DEBUG : BROWSER_OUTPUT: 14:04:24 INFO - 2015-10-23 14:04:24,201 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634264196__endTimestamp 14:04:24 INFO - 2015-10-23 14:04:24,931 INFO : Browser exited with error code: 0 14:04:24 INFO - 2015-10-23 14:04:24,932 INFO : Running cycle 10/20 for ts_paint test... 14:04:24 INFO - 2015-10-23 14:04:24,932 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:26 INFO - 2015-10-23 14:04:26,199 DEBUG : BROWSER_OUTPUT: __start_report1264__end_report 14:04:26 INFO - 2015-10-23 14:04:26,199 DEBUG : BROWSER_OUTPUT: 14:04:26 INFO - 2015-10-23 14:04:26,214 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634266212__endTimestamp 14:04:26 INFO - 2015-10-23 14:04:26,951 INFO : Browser exited with error code: 0 14:04:26 INFO - 2015-10-23 14:04:26,952 INFO : Running cycle 11/20 for ts_paint test... 14:04:26 INFO - 2015-10-23 14:04:26,952 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:28 INFO - 2015-10-23 14:04:28,243 DEBUG : BROWSER_OUTPUT: __start_report1288__end_report 14:04:28 INFO - 2015-10-23 14:04:28,244 DEBUG : BROWSER_OUTPUT: 14:04:28 INFO - 2015-10-23 14:04:28,259 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634268256__endTimestamp 14:04:28 INFO - 2015-10-23 14:04:28,987 INFO : Browser exited with error code: 0 14:04:28 INFO - 2015-10-23 14:04:28,988 INFO : Running cycle 12/20 for ts_paint test... 14:04:28 INFO - 2015-10-23 14:04:28,988 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:30 INFO - 2015-10-23 14:04:30,267 DEBUG : BROWSER_OUTPUT: __start_report1269__end_report 14:04:30 INFO - 2015-10-23 14:04:30,267 DEBUG : BROWSER_OUTPUT: 14:04:30 INFO - 2015-10-23 14:04:30,276 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634270273__endTimestamp 14:04:31 INFO - 2015-10-23 14:04:31,032 INFO : Browser exited with error code: 0 14:04:31 INFO - 2015-10-23 14:04:31,034 INFO : Running cycle 13/20 for ts_paint test... 14:04:31 INFO - 2015-10-23 14:04:31,034 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:32 INFO - 2015-10-23 14:04:32,299 DEBUG : BROWSER_OUTPUT: __start_report1261__end_report 14:04:32 INFO - 2015-10-23 14:04:32,300 DEBUG : BROWSER_OUTPUT: 14:04:32 INFO - 2015-10-23 14:04:32,315 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634272312__endTimestamp 14:04:33 INFO - 2015-10-23 14:04:33,069 INFO : Browser exited with error code: 0 14:04:33 INFO - 2015-10-23 14:04:33,070 INFO : Running cycle 14/20 for ts_paint test... 14:04:33 INFO - 2015-10-23 14:04:33,070 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:34 INFO - 2015-10-23 14:04:34,364 DEBUG : BROWSER_OUTPUT: __start_report1291__end_report 14:04:34 INFO - 2015-10-23 14:04:34,365 DEBUG : BROWSER_OUTPUT: 14:04:34 INFO - 2015-10-23 14:04:34,373 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634274370__endTimestamp 14:04:35 INFO - 2015-10-23 14:04:35,091 INFO : Browser exited with error code: 0 14:04:35 INFO - 2015-10-23 14:04:35,093 INFO : Running cycle 15/20 for ts_paint test... 14:04:35 INFO - 2015-10-23 14:04:35,093 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:36 INFO - 2015-10-23 14:04:36,372 DEBUG : BROWSER_OUTPUT: __start_report1271__end_report 14:04:36 INFO - 2015-10-23 14:04:36,372 DEBUG : BROWSER_OUTPUT: 14:04:36 INFO - 2015-10-23 14:04:36,381 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634276380__endTimestamp 14:04:37 INFO - 2015-10-23 14:04:37,136 INFO : Browser exited with error code: 0 14:04:37 INFO - 2015-10-23 14:04:37,137 INFO : Running cycle 16/20 for ts_paint test... 14:04:37 INFO - 2015-10-23 14:04:37,137 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:38 INFO - 2015-10-23 14:04:38,430 DEBUG : BROWSER_OUTPUT: __start_report1291__end_report 14:04:38 INFO - 2015-10-23 14:04:38,431 DEBUG : BROWSER_OUTPUT: 14:04:38 INFO - 2015-10-23 14:04:38,438 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634278437__endTimestamp 14:04:39 INFO - 2015-10-23 14:04:39,180 INFO : Browser exited with error code: 0 14:04:39 INFO - 2015-10-23 14:04:39,181 INFO : Running cycle 17/20 for ts_paint test... 14:04:39 INFO - 2015-10-23 14:04:39,181 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:40 INFO - 2015-10-23 14:04:40,452 DEBUG : BROWSER_OUTPUT: __start_report1266__end_report 14:04:40 INFO - 2015-10-23 14:04:40,452 DEBUG : BROWSER_OUTPUT: 14:04:40 INFO - 2015-10-23 14:04:40,468 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634280463__endTimestamp 14:04:41 INFO - 2015-10-23 14:04:41,220 INFO : Browser exited with error code: 0 14:04:41 INFO - 2015-10-23 14:04:41,221 INFO : Running cycle 18/20 for ts_paint test... 14:04:41 INFO - 2015-10-23 14:04:41,221 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:42 INFO - 2015-10-23 14:04:42,483 DEBUG : BROWSER_OUTPUT: __start_report1260__end_report 14:04:42 INFO - 2015-10-23 14:04:42,483 DEBUG : BROWSER_OUTPUT: 14:04:42 INFO - 2015-10-23 14:04:42,499 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634282496__endTimestamp 14:04:43 INFO - 2015-10-23 14:04:43,276 INFO : Browser exited with error code: 0 14:04:43 INFO - 2015-10-23 14:04:43,278 INFO : Running cycle 19/20 for ts_paint test... 14:04:43 INFO - 2015-10-23 14:04:43,278 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:44 INFO - 2015-10-23 14:04:44,551 DEBUG : BROWSER_OUTPUT: __start_report1269__end_report 14:04:44 INFO - 2015-10-23 14:04:44,551 DEBUG : BROWSER_OUTPUT: 14:04:44 INFO - 2015-10-23 14:04:44,568 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634284563__endTimestamp 14:04:45 INFO - 2015-10-23 14:04:45,373 INFO : Browser exited with error code: 0 14:04:45 INFO - 2015-10-23 14:04:45,374 INFO : Running cycle 20/20 for ts_paint test... 14:04:45 INFO - 2015-10-23 14:04:45,374 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpigpEZu/profile http://localhost:49269/startup_test/tspaint_test.html 14:04:46 INFO - 2015-10-23 14:04:46,646 DEBUG : BROWSER_OUTPUT: __start_report1266__end_report 14:04:46 INFO - 2015-10-23 14:04:46,646 DEBUG : BROWSER_OUTPUT: 14:04:46 INFO - 2015-10-23 14:04:46,661 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634286656__endTimestamp 14:04:47 INFO - 2015-10-23 14:04:47,419 INFO : Browser exited with error code: 0 14:04:47 INFO - 2015-10-23 14:04:47,446 INFO : Completed test ts_paint (00:00:43) 14:04:47 INFO - 2015-10-23 14:04:47,446 INFO : Starting test tpaint 14:04:47 INFO - 2015-10-23 14:04:47,446 DEBUG : operating with platform_type : mac_ 14:04:47 INFO - 2015-10-23 14:04:47,447 INFO : Initialising browser for tpaint test... 14:04:47 INFO - 2015-10-23 14:04:47,462 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmp9R_cob/profile http://localhost:49269/getInfo.html 14:04:49 INFO - 2015-10-23 14:04:49,624 DEBUG : BROWSER_OUTPUT: __metrics Screen width/height:1600/1200 14:04:49 INFO - 2015-10-23 14:04:49,624 DEBUG : BROWSER_OUTPUT: colorDepth:24 14:04:49 INFO - 2015-10-23 14:04:49,626 DEBUG : BROWSER_OUTPUT: Browser inner width/height: 1024/689 14:04:49 INFO - 2015-10-23 14:04:49,626 DEBUG : BROWSER_OUTPUT: __metrics 14:04:49 INFO - 2015-10-23 14:04:49,642 DEBUG : BROWSER_OUTPUT: JavaScript error: resource:///modules/WebappManager.jsm, line 48: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver] 14:04:50 INFO - 2015-10-23 14:04:50,375 INFO : Browser initialized. 14:04:50 INFO - 2015-10-23 14:04:50,376 INFO : Running cycle 1/1 for tpaint test... 14:04:50 INFO - 2015-10-23 14:04:50,376 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmp9R_cob/profile file:///builds/slave/test/build/tests/talos/talos/startup_test/tpaint.html?auto=1 14:05:19 INFO - 2015-10-23 14:05:19,192 DEBUG : BROWSER_OUTPUT: __start_report308.40499999999975|312.60000000000036|314.58500000000004|316.6750000000002|317.3250000000007|319.28500000000076|324.3050000000003|324.4150000000009|326.16499999999905|326.72000000000116|327.2449999999999|332.02999999999884|333.6350000000002|339.375|342.7099999999991|345.5099999999984|359.58500000000276|404.65500000000065|405.5300000000025|505.35000000000036__end_report__startTimestamp1445634319190__endTimestamp 14:05:19 INFO - 2015-10-23 14:05:19,192 DEBUG : BROWSER_OUTPUT: openingTimes=312.60000000000036,314.58500000000004,316.6750000000002,317.3250000000007,319.28500000000076,324.3050000000003,324.4150000000009,326.16499999999905,326.72000000000116,327.2449999999999,332.02999999999884,333.6350000000002,339.375,342.7099999999991,345.5099999999984,359.58500000000276,404.65500000000065,405.5300000000025,505.35000000000036 14:05:19 INFO - 2015-10-23 14:05:19,192 DEBUG : BROWSER_OUTPUT: avgOpenTime:344.31 14:05:19 INFO - 2015-10-23 14:05:19,192 DEBUG : BROWSER_OUTPUT: minOpenTime:308.40 14:05:19 INFO - 2015-10-23 14:05:19,192 DEBUG : BROWSER_OUTPUT: maxOpenTime:505.35 14:05:19 INFO - 2015-10-23 14:05:19,192 DEBUG : BROWSER_OUTPUT: medOpenTime:326.9825000000005 14:05:19 INFO - 2015-10-23 14:05:19,192 DEBUG : BROWSER_OUTPUT: __xulWinOpenTime:326.9825000000005 14:05:19 INFO - 2015-10-23 14:05:19,929 INFO : Browser exited with error code: 0 14:05:19 INFO - 2015-10-23 14:05:19,947 INFO : Completed test tpaint (00:00:32) 14:05:19 INFO - 2015-10-23 14:05:19,947 INFO : Starting test sessionrestore 14:05:19 INFO - 2015-10-23 14:05:19,948 DEBUG : operating with platform_type : mac_ 14:05:19 INFO - 2015-10-23 14:05:19,948 INFO : Initialising browser for sessionrestore test... 14:05:19 INFO - 2015-10-23 14:05:19,966 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile http://localhost:49269/getInfo.html 14:05:25 INFO - 2015-10-23 14:05:25,321 DEBUG : BROWSER_OUTPUT: __metrics Screen width/height:1600/1200 14:05:25 INFO - 2015-10-23 14:05:25,321 DEBUG : BROWSER_OUTPUT: colorDepth:24 14:05:25 INFO - 2015-10-23 14:05:25,322 DEBUG : BROWSER_OUTPUT: Browser inner width/height: 1200/743 14:05:25 INFO - 2015-10-23 14:05:25,322 DEBUG : BROWSER_OUTPUT: __metrics 14:05:25 INFO - 2015-10-23 14:05:25,407 DEBUG : BROWSER_OUTPUT: JavaScript error: resource:///modules/WebappManager.jsm, line 48: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver] 14:05:26 INFO - 2015-10-23 14:05:26,156 DEBUG : BROWSER_OUTPUT: console.error: 14:05:26 INFO - 2015-10-23 14:05:26,157 DEBUG : BROWSER_OUTPUT: Message: [Exception... "Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [mozIStorageAsyncStatement.executeAsync]" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "JS frame :: resource://gre/modules/Sqlite.jsm :: ConnectionData.prototype<._executeStatement :: line 758" data: no] 14:05:26 INFO - 2015-10-23 14:05:26,157 DEBUG : BROWSER_OUTPUT: Stack: 14:05:26 INFO - 2015-10-23 14:05:26,158 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<._executeStatement@resource://gre/modules/Sqlite.jsm:758:19 14:05:26 INFO - 2015-10-23 14:05:26,158 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<.executeCached/<@resource://gre/modules/Sqlite.jsm:493:9 14:05:26 INFO - 2015-10-23 14:05:26,158 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<.executeCached@resource://gre/modules/Sqlite.jsm:491:1 14:05:26 INFO - 2015-10-23 14:05:26,158 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<.executeBeforeShutdown/loggedDb<.executeCached.value<@resource://gre/modules/Sqlite.jsm:368:51 14:05:26 INFO - 2015-10-23 14:05:26,158 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:314:40 14:05:26 INFO - 2015-10-23 14:05:26,158 DEBUG : BROWSER_OUTPUT: TaskImpl@resource://gre/modules/Task.jsm:275:3 14:05:26 INFO - 2015-10-23 14:05:26,158 DEBUG : BROWSER_OUTPUT: createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:249:14 14:05:26 INFO - 2015-10-23 14:05:26,159 DEBUG : BROWSER_OUTPUT: setAncestorsLastModified<@resource://gre/modules/Bookmarks.jsm:1347:9 14:05:26 INFO - 2015-10-23 14:05:26,159 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:314:40 14:05:26 INFO - 2015-10-23 14:05:26,159 DEBUG : BROWSER_OUTPUT: TaskImpl@resource://gre/modules/Task.jsm:275:3 14:05:26 INFO - 2015-10-23 14:05:26,159 DEBUG : BROWSER_OUTPUT: createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:249:14 14:05:26 INFO - 2015-10-23 14:05:26,159 DEBUG : BROWSER_OUTPUT: transaction@resource://gre/modules/Bookmarks.jsm:808:13 14:05:26 INFO - 2015-10-23 14:05:26,159 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:314:40 14:05:26 INFO - 2015-10-23 14:05:26,161 DEBUG : BROWSER_OUTPUT: Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:934:23 14:05:26 INFO - 2015-10-23 14:05:26,161 DEBUG : BROWSER_OUTPUT: this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:813:7 14:05:26 INFO - 2015-10-23 14:05:26,161 DEBUG : BROWSER_OUTPUT: Promise*this.PromiseWalker.scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:744:11 14:05:26 INFO - 2015-10-23 14:05:26,161 DEBUG : BROWSER_OUTPUT: this.PromiseWalker.schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:776:7 14:05:26 INFO - 2015-10-23 14:05:26,161 DEBUG : BROWSER_OUTPUT: this.PromiseWalker.completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:711:7 14:05:26 INFO - 2015-10-23 14:05:26,161 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:319:13 14:05:26 INFO - 2015-10-23 14:05:26,161 DEBUG : BROWSER_OUTPUT: Spinner.prototype.observe@resource://gre/modules/AsyncShutdown.jsm:523:9 14:05:26 INFO - 2015-10-23 14:05:26,161 DEBUG : BROWSER_OUTPUT: 14:05:26 INFO - 2015-10-23 14:05:26,602 INFO : Browser initialized. 14:05:26 INFO - 2015-10-23 14:05:26,602 INFO : Running cycle 1/10 for sessionrestore test... 14:05:26 INFO - 2015-10-23 14:05:26,602 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionstore.js 14:05:26 INFO - 2015-10-23 14:05:26,605 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionCheckpoints.json 14:05:26 INFO - 2015-10-23 14:05:26,606 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:05:31 INFO - 2015-10-23 14:05:31,636 DEBUG : BROWSER_OUTPUT: __start_report2664__end_report 14:05:31 INFO - 2015-10-23 14:05:31,636 DEBUG : BROWSER_OUTPUT: 14:05:31 INFO - 2015-10-23 14:05:31,636 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634331630__endTimestamp 14:05:31 INFO - 2015-10-23 14:05:31,636 DEBUG : BROWSER_OUTPUT: 14:05:32 INFO - 2015-10-23 14:05:32,907 INFO : Browser exited with error code: 0 14:05:32 INFO - 2015-10-23 14:05:32,909 INFO : Running cycle 2/10 for sessionrestore test... 14:05:32 INFO - 2015-10-23 14:05:32,909 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionstore.js 14:05:32 INFO - 2015-10-23 14:05:32,929 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionCheckpoints.json 14:05:32 INFO - 2015-10-23 14:05:32,929 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:05:37 INFO - 2015-10-23 14:05:37,330 DEBUG : BROWSER_OUTPUT: __start_report2364__end_report 14:05:37 INFO - 2015-10-23 14:05:37,330 DEBUG : BROWSER_OUTPUT: 14:05:37 INFO - 2015-10-23 14:05:37,330 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634337329__endTimestamp 14:05:37 INFO - 2015-10-23 14:05:37,330 DEBUG : BROWSER_OUTPUT: 14:05:38 INFO - 2015-10-23 14:05:38,670 INFO : Browser exited with error code: 0 14:05:38 INFO - 2015-10-23 14:05:38,671 INFO : Running cycle 3/10 for sessionrestore test... 14:05:38 INFO - 2015-10-23 14:05:38,671 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionstore.js 14:05:38 INFO - 2015-10-23 14:05:38,674 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionCheckpoints.json 14:05:38 INFO - 2015-10-23 14:05:38,675 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:05:43 INFO - 2015-10-23 14:05:43,085 DEBUG : BROWSER_OUTPUT: __start_report2370__end_report 14:05:43 INFO - 2015-10-23 14:05:43,085 DEBUG : BROWSER_OUTPUT: 14:05:43 INFO - 2015-10-23 14:05:43,086 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634343081__endTimestamp 14:05:43 INFO - 2015-10-23 14:05:43,086 DEBUG : BROWSER_OUTPUT: 14:05:44 INFO - 2015-10-23 14:05:44,447 INFO : Browser exited with error code: 0 14:05:44 INFO - 2015-10-23 14:05:44,448 INFO : Running cycle 4/10 for sessionrestore test... 14:05:44 INFO - 2015-10-23 14:05:44,448 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionstore.js 14:05:44 INFO - 2015-10-23 14:05:44,452 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionCheckpoints.json 14:05:44 INFO - 2015-10-23 14:05:44,452 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:05:48 INFO - 2015-10-23 14:05:48,917 DEBUG : BROWSER_OUTPUT: __start_report2394__end_report 14:05:48 INFO - 2015-10-23 14:05:48,917 DEBUG : BROWSER_OUTPUT: 14:05:48 INFO - 2015-10-23 14:05:48,917 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634348913__endTimestamp 14:05:48 INFO - 2015-10-23 14:05:48,917 DEBUG : BROWSER_OUTPUT: 14:05:50 INFO - 2015-10-23 14:05:50,351 INFO : Browser exited with error code: 0 14:05:50 INFO - 2015-10-23 14:05:50,353 INFO : Running cycle 5/10 for sessionrestore test... 14:05:50 INFO - 2015-10-23 14:05:50,353 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionstore.js 14:05:50 INFO - 2015-10-23 14:05:50,355 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionCheckpoints.json 14:05:50 INFO - 2015-10-23 14:05:50,355 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:05:54 INFO - 2015-10-23 14:05:54,779 DEBUG : BROWSER_OUTPUT: __start_report2376__end_report 14:05:54 INFO - 2015-10-23 14:05:54,779 DEBUG : BROWSER_OUTPUT: 14:05:54 INFO - 2015-10-23 14:05:54,779 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634354775__endTimestamp 14:05:54 INFO - 2015-10-23 14:05:54,779 DEBUG : BROWSER_OUTPUT: 14:05:56 INFO - 2015-10-23 14:05:56,217 INFO : Browser exited with error code: 0 14:05:56 INFO - 2015-10-23 14:05:56,218 INFO : Running cycle 6/10 for sessionrestore test... 14:05:56 INFO - 2015-10-23 14:05:56,218 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionstore.js 14:05:56 INFO - 2015-10-23 14:05:56,235 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionCheckpoints.json 14:05:56 INFO - 2015-10-23 14:05:56,235 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:00 INFO - 2015-10-23 14:06:00,666 DEBUG : BROWSER_OUTPUT: __start_report2385__end_report 14:06:00 INFO - 2015-10-23 14:06:00,666 DEBUG : BROWSER_OUTPUT: 14:06:00 INFO - 2015-10-23 14:06:00,666 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634360665__endTimestamp 14:06:00 INFO - 2015-10-23 14:06:00,666 DEBUG : BROWSER_OUTPUT: 14:06:02 INFO - 2015-10-23 14:06:02,134 INFO : Browser exited with error code: 0 14:06:02 INFO - 2015-10-23 14:06:02,136 INFO : Running cycle 7/10 for sessionrestore test... 14:06:02 INFO - 2015-10-23 14:06:02,136 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionstore.js 14:06:02 INFO - 2015-10-23 14:06:02,141 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionCheckpoints.json 14:06:02 INFO - 2015-10-23 14:06:02,142 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:06 INFO - 2015-10-23 14:06:06,546 DEBUG : BROWSER_OUTPUT: __start_report2369__end_report 14:06:06 INFO - 2015-10-23 14:06:06,547 DEBUG : BROWSER_OUTPUT: 14:06:06 INFO - 2015-10-23 14:06:06,547 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634366543__endTimestamp 14:06:06 INFO - 2015-10-23 14:06:06,547 DEBUG : BROWSER_OUTPUT: 14:06:07 INFO - 2015-10-23 14:06:07,961 INFO : Browser exited with error code: 0 14:06:07 INFO - 2015-10-23 14:06:07,962 INFO : Running cycle 8/10 for sessionrestore test... 14:06:07 INFO - 2015-10-23 14:06:07,962 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionstore.js 14:06:07 INFO - 2015-10-23 14:06:07,985 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionCheckpoints.json 14:06:07 INFO - 2015-10-23 14:06:07,986 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:12 INFO - 2015-10-23 14:06:12,404 DEBUG : BROWSER_OUTPUT: __start_report2373__end_report 14:06:12 INFO - 2015-10-23 14:06:12,404 DEBUG : BROWSER_OUTPUT: 14:06:12 INFO - 2015-10-23 14:06:12,404 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634372399__endTimestamp 14:06:12 INFO - 2015-10-23 14:06:12,404 DEBUG : BROWSER_OUTPUT: 14:06:13 INFO - 2015-10-23 14:06:13,846 INFO : Browser exited with error code: 0 14:06:13 INFO - 2015-10-23 14:06:13,848 INFO : Running cycle 9/10 for sessionrestore test... 14:06:13 INFO - 2015-10-23 14:06:13,848 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionstore.js 14:06:13 INFO - 2015-10-23 14:06:13,854 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionCheckpoints.json 14:06:13 INFO - 2015-10-23 14:06:13,854 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:18 INFO - 2015-10-23 14:06:18,286 DEBUG : BROWSER_OUTPUT: __start_report2363__end_report 14:06:18 INFO - 2015-10-23 14:06:18,287 DEBUG : BROWSER_OUTPUT: 14:06:18 INFO - 2015-10-23 14:06:18,287 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634378285__endTimestamp 14:06:18 INFO - 2015-10-23 14:06:18,287 DEBUG : BROWSER_OUTPUT: 14:06:19 INFO - 2015-10-23 14:06:19,728 INFO : Browser exited with error code: 0 14:06:19 INFO - 2015-10-23 14:06:19,729 INFO : Running cycle 10/10 for sessionrestore test... 14:06:19 INFO - 2015-10-23 14:06:19,729 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionstore.js 14:06:19 INFO - 2015-10-23 14:06:19,738 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile/sessionCheckpoints.json 14:06:19 INFO - 2015-10-23 14:06:19,738 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpd1WW8V/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:24 INFO - 2015-10-23 14:06:24,167 DEBUG : BROWSER_OUTPUT: __start_report2383__end_report 14:06:24 INFO - 2015-10-23 14:06:24,167 DEBUG : BROWSER_OUTPUT: 14:06:24 INFO - 2015-10-23 14:06:24,167 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634384162__endTimestamp 14:06:24 INFO - 2015-10-23 14:06:24,167 DEBUG : BROWSER_OUTPUT: 14:06:25 INFO - 2015-10-23 14:06:25,635 INFO : Browser exited with error code: 0 14:06:25 INFO - 2015-10-23 14:06:25,659 INFO : Completed test sessionrestore (00:01:05) 14:06:25 INFO - 2015-10-23 14:06:25,659 INFO : Starting test sessionrestore_no_auto_restore 14:06:25 INFO - 2015-10-23 14:06:25,659 DEBUG : operating with platform_type : mac_ 14:06:25 INFO - 2015-10-23 14:06:25,660 INFO : Initialising browser for sessionrestore_no_auto_restore test... 14:06:25 INFO - 2015-10-23 14:06:25,681 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile http://localhost:49269/getInfo.html 14:06:27 INFO - 2015-10-23 14:06:27,905 DEBUG : BROWSER_OUTPUT: __metrics Screen width/height:1600/1200 14:06:27 INFO - 2015-10-23 14:06:27,905 DEBUG : BROWSER_OUTPUT: colorDepth:24 14:06:27 INFO - 2015-10-23 14:06:27,905 DEBUG : BROWSER_OUTPUT: Browser inner width/height: 1200/743 14:06:27 INFO - 2015-10-23 14:06:27,905 DEBUG : BROWSER_OUTPUT: __metrics 14:06:27 INFO - 2015-10-23 14:06:27,921 DEBUG : BROWSER_OUTPUT: JavaScript error: resource:///modules/WebappManager.jsm, line 48: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver] 14:06:28 INFO - 2015-10-23 14:06:28,193 DEBUG : BROWSER_OUTPUT: console.error: 14:06:28 INFO - 2015-10-23 14:06:28,193 DEBUG : BROWSER_OUTPUT: Message: [Exception... "Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [mozIStorageAsyncStatement.executeAsync]" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "JS frame :: resource://gre/modules/Sqlite.jsm :: ConnectionData.prototype<._executeStatement :: line 758" data: no] 14:06:28 INFO - 2015-10-23 14:06:28,194 DEBUG : BROWSER_OUTPUT: Stack: 14:06:28 INFO - 2015-10-23 14:06:28,194 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<._executeStatement@resource://gre/modules/Sqlite.jsm:758:19 14:06:28 INFO - 2015-10-23 14:06:28,194 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<.executeCached/<@resource://gre/modules/Sqlite.jsm:493:9 14:06:28 INFO - 2015-10-23 14:06:28,194 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<.executeCached@resource://gre/modules/Sqlite.jsm:491:1 14:06:28 INFO - 2015-10-23 14:06:28,194 DEBUG : BROWSER_OUTPUT: ConnectionData.prototype<.executeBeforeShutdown/loggedDb<.executeCached.value<@resource://gre/modules/Sqlite.jsm:368:51 14:06:28 INFO - 2015-10-23 14:06:28,194 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:314:40 14:06:28 INFO - 2015-10-23 14:06:28,194 DEBUG : BROWSER_OUTPUT: TaskImpl@resource://gre/modules/Task.jsm:275:3 14:06:28 INFO - 2015-10-23 14:06:28,194 DEBUG : BROWSER_OUTPUT: createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:249:14 14:06:28 INFO - 2015-10-23 14:06:28,194 DEBUG : BROWSER_OUTPUT: setAncestorsLastModified<@resource://gre/modules/Bookmarks.jsm:1347:9 14:06:28 INFO - 2015-10-23 14:06:28,194 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:314:40 14:06:28 INFO - 2015-10-23 14:06:28,194 DEBUG : BROWSER_OUTPUT: TaskImpl@resource://gre/modules/Task.jsm:275:3 14:06:28 INFO - 2015-10-23 14:06:28,195 DEBUG : BROWSER_OUTPUT: createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:249:14 14:06:28 INFO - 2015-10-23 14:06:28,195 DEBUG : BROWSER_OUTPUT: transaction@resource://gre/modules/Bookmarks.jsm:808:13 14:06:28 INFO - 2015-10-23 14:06:28,195 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:314:40 14:06:28 INFO - 2015-10-23 14:06:28,195 DEBUG : BROWSER_OUTPUT: Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:934:23 14:06:28 INFO - 2015-10-23 14:06:28,195 DEBUG : BROWSER_OUTPUT: this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:813:7 14:06:28 INFO - 2015-10-23 14:06:28,195 DEBUG : BROWSER_OUTPUT: Promise*this.PromiseWalker.scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:744:11 14:06:28 INFO - 2015-10-23 14:06:28,195 DEBUG : BROWSER_OUTPUT: this.PromiseWalker.schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:776:7 14:06:28 INFO - 2015-10-23 14:06:28,195 DEBUG : BROWSER_OUTPUT: this.PromiseWalker.completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:711:7 14:06:28 INFO - 2015-10-23 14:06:28,195 DEBUG : BROWSER_OUTPUT: TaskImpl_run@resource://gre/modules/Task.jsm:319:13 14:06:28 INFO - 2015-10-23 14:06:28,195 DEBUG : BROWSER_OUTPUT: Spinner.prototype.observe@resource://gre/modules/AsyncShutdown.jsm:523:9 14:06:28 INFO - 2015-10-23 14:06:28,195 DEBUG : BROWSER_OUTPUT: 14:06:28 INFO - 2015-10-23 14:06:28,635 INFO : Browser initialized. 14:06:28 INFO - 2015-10-23 14:06:28,635 INFO : Running cycle 1/10 for sessionrestore_no_auto_restore test... 14:06:28 INFO - 2015-10-23 14:06:28,635 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionstore.js 14:06:28 INFO - 2015-10-23 14:06:28,641 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionCheckpoints.json 14:06:28 INFO - 2015-10-23 14:06:28,642 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:30 INFO - 2015-10-23 14:06:30,506 DEBUG : BROWSER_OUTPUT: __start_report1278__end_report 14:06:30 INFO - 2015-10-23 14:06:30,506 DEBUG : BROWSER_OUTPUT: 14:06:30 INFO - 2015-10-23 14:06:30,507 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634390505__endTimestamp 14:06:30 INFO - 2015-10-23 14:06:30,507 DEBUG : BROWSER_OUTPUT: 14:06:31 INFO - 2015-10-23 14:06:31,223 INFO : Browser exited with error code: 0 14:06:31 INFO - 2015-10-23 14:06:31,224 INFO : Running cycle 2/10 for sessionrestore_no_auto_restore test... 14:06:31 INFO - 2015-10-23 14:06:31,224 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionstore.js 14:06:31 INFO - 2015-10-23 14:06:31,230 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionCheckpoints.json 14:06:31 INFO - 2015-10-23 14:06:31,230 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:32 INFO - 2015-10-23 14:06:32,655 DEBUG : BROWSER_OUTPUT: __start_report980__end_report 14:06:32 INFO - 2015-10-23 14:06:32,656 DEBUG : BROWSER_OUTPUT: 14:06:32 INFO - 2015-10-23 14:06:32,656 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634392648__endTimestamp 14:06:32 INFO - 2015-10-23 14:06:32,656 DEBUG : BROWSER_OUTPUT: 14:06:33 INFO - 2015-10-23 14:06:33,347 INFO : Browser exited with error code: 0 14:06:33 INFO - 2015-10-23 14:06:33,349 INFO : Running cycle 3/10 for sessionrestore_no_auto_restore test... 14:06:33 INFO - 2015-10-23 14:06:33,349 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionstore.js 14:06:33 INFO - 2015-10-23 14:06:33,354 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionCheckpoints.json 14:06:33 INFO - 2015-10-23 14:06:33,355 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:34 INFO - 2015-10-23 14:06:34,767 DEBUG : BROWSER_OUTPUT: __start_report972__end_report 14:06:34 INFO - 2015-10-23 14:06:34,768 DEBUG : BROWSER_OUTPUT: 14:06:34 INFO - 2015-10-23 14:06:34,768 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634394765__endTimestamp 14:06:34 INFO - 2015-10-23 14:06:34,768 DEBUG : BROWSER_OUTPUT: 14:06:35 INFO - 2015-10-23 14:06:35,538 INFO : Browser exited with error code: 0 14:06:35 INFO - 2015-10-23 14:06:35,539 INFO : Running cycle 4/10 for sessionrestore_no_auto_restore test... 14:06:35 INFO - 2015-10-23 14:06:35,539 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionstore.js 14:06:35 INFO - 2015-10-23 14:06:35,545 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionCheckpoints.json 14:06:35 INFO - 2015-10-23 14:06:35,546 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:36 INFO - 2015-10-23 14:06:36,972 DEBUG : BROWSER_OUTPUT: __start_report983__end_report 14:06:36 INFO - 2015-10-23 14:06:36,973 DEBUG : BROWSER_OUTPUT: 14:06:36 INFO - 2015-10-23 14:06:36,973 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634396969__endTimestamp 14:06:36 INFO - 2015-10-23 14:06:36,973 DEBUG : BROWSER_OUTPUT: 14:06:37 INFO - 2015-10-23 14:06:37,746 INFO : Browser exited with error code: 0 14:06:37 INFO - 2015-10-23 14:06:37,747 INFO : Running cycle 5/10 for sessionrestore_no_auto_restore test... 14:06:37 INFO - 2015-10-23 14:06:37,748 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionstore.js 14:06:37 INFO - 2015-10-23 14:06:37,756 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionCheckpoints.json 14:06:37 INFO - 2015-10-23 14:06:37,757 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:39 INFO - 2015-10-23 14:06:39,170 DEBUG : BROWSER_OUTPUT: __start_report965__end_report 14:06:39 INFO - 2015-10-23 14:06:39,171 DEBUG : BROWSER_OUTPUT: 14:06:39 INFO - 2015-10-23 14:06:39,171 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634399167__endTimestamp 14:06:39 INFO - 2015-10-23 14:06:39,171 DEBUG : BROWSER_OUTPUT: 14:06:39 INFO - 2015-10-23 14:06:39,990 INFO : Browser exited with error code: 0 14:06:39 INFO - 2015-10-23 14:06:39,991 INFO : Running cycle 6/10 for sessionrestore_no_auto_restore test... 14:06:39 INFO - 2015-10-23 14:06:39,992 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionstore.js 14:06:39 INFO - 2015-10-23 14:06:39,998 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionCheckpoints.json 14:06:39 INFO - 2015-10-23 14:06:39,998 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:41 INFO - 2015-10-23 14:06:41,422 DEBUG : BROWSER_OUTPUT: __start_report968__end_report 14:06:41 INFO - 2015-10-23 14:06:41,422 DEBUG : BROWSER_OUTPUT: 14:06:41 INFO - 2015-10-23 14:06:41,423 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634401417__endTimestamp 14:06:41 INFO - 2015-10-23 14:06:41,423 DEBUG : BROWSER_OUTPUT: 14:06:42 INFO - 2015-10-23 14:06:42,221 INFO : Browser exited with error code: 0 14:06:42 INFO - 2015-10-23 14:06:42,223 INFO : Running cycle 7/10 for sessionrestore_no_auto_restore test... 14:06:42 INFO - 2015-10-23 14:06:42,223 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionstore.js 14:06:42 INFO - 2015-10-23 14:06:42,232 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionCheckpoints.json 14:06:42 INFO - 2015-10-23 14:06:42,232 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:43 INFO - 2015-10-23 14:06:43,656 DEBUG : BROWSER_OUTPUT: __start_report970__end_report 14:06:43 INFO - 2015-10-23 14:06:43,657 DEBUG : BROWSER_OUTPUT: 14:06:43 INFO - 2015-10-23 14:06:43,657 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634403650__endTimestamp 14:06:43 INFO - 2015-10-23 14:06:43,657 DEBUG : BROWSER_OUTPUT: 14:06:44 INFO - 2015-10-23 14:06:44,482 INFO : Browser exited with error code: 0 14:06:44 INFO - 2015-10-23 14:06:44,483 INFO : Running cycle 8/10 for sessionrestore_no_auto_restore test... 14:06:44 INFO - 2015-10-23 14:06:44,484 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionstore.js 14:06:44 INFO - 2015-10-23 14:06:44,489 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionCheckpoints.json 14:06:44 INFO - 2015-10-23 14:06:44,489 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:45 INFO - 2015-10-23 14:06:45,923 DEBUG : BROWSER_OUTPUT: __start_report976__end_report 14:06:45 INFO - 2015-10-23 14:06:45,923 DEBUG : BROWSER_OUTPUT: 14:06:45 INFO - 2015-10-23 14:06:45,923 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634405920__endTimestamp 14:06:45 INFO - 2015-10-23 14:06:45,923 DEBUG : BROWSER_OUTPUT: 14:06:46 INFO - 2015-10-23 14:06:46,744 INFO : Browser exited with error code: 0 14:06:46 INFO - 2015-10-23 14:06:46,746 INFO : Running cycle 9/10 for sessionrestore_no_auto_restore test... 14:06:46 INFO - 2015-10-23 14:06:46,746 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionstore.js 14:06:46 INFO - 2015-10-23 14:06:46,754 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionCheckpoints.json 14:06:46 INFO - 2015-10-23 14:06:46,755 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:48 INFO - 2015-10-23 14:06:48,184 DEBUG : BROWSER_OUTPUT: __start_report982__end_report 14:06:48 INFO - 2015-10-23 14:06:48,184 DEBUG : BROWSER_OUTPUT: 14:06:48 INFO - 2015-10-23 14:06:48,184 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634408183__endTimestamp 14:06:48 INFO - 2015-10-23 14:06:48,184 DEBUG : BROWSER_OUTPUT: 14:06:49 INFO - 2015-10-23 14:06:49,021 INFO : Browser exited with error code: 0 14:06:49 INFO - 2015-10-23 14:06:49,022 INFO : Running cycle 10/10 for sessionrestore_no_auto_restore test... 14:06:49 INFO - 2015-10-23 14:06:49,022 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionstore.js on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionstore.js 14:06:49 INFO - 2015-10-23 14:06:49,028 DEBUG : Reinstalling /builds/slave/test/build/tests/talos/talos/startup_test/sessionrestore/profile/sessionCheckpoints.json on top of /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile/sessionCheckpoints.json 14:06:49 INFO - 2015-10-23 14:06:49,028 DEBUG : command line: /builds/slave/test/build/application/Nightly.app/Contents/MacOS/firefox -foreground -profile /var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/tmpYuufqx/profile http://localhost:49269/startup_test/sessionrestore/index.html 14:06:50 INFO - 2015-10-23 14:06:50,452 DEBUG : BROWSER_OUTPUT: __start_report973__end_report 14:06:50 INFO - 2015-10-23 14:06:50,452 DEBUG : BROWSER_OUTPUT: 14:06:50 INFO - 2015-10-23 14:06:50,452 DEBUG : BROWSER_OUTPUT: __startTimestamp1445634410451__endTimestamp 14:06:50 INFO - 2015-10-23 14:06:50,452 DEBUG : BROWSER_OUTPUT: 14:06:51 INFO - 2015-10-23 14:06:51,302 INFO : Browser exited with error code: 0 14:06:51 INFO - 2015-10-23 14:06:51,324 INFO : Completed test sessionrestore_no_auto_restore (00:00:25) 14:06:51 INFO - 2015-10-23 14:06:51,349 INFO : Completed test suite (00:04:23) 14:06:51 INFO - 2015-10-23 14:06:51,350 DEBUG : Working with test: a11yr 14:06:51 INFO - 2015-10-23 14:06:51,350 DEBUG : Generating results file: a11yr 14:06:51 INFO - 2015-10-23 14:06:51,350 DEBUG : Working with test: ts_paint 14:06:51 INFO - 2015-10-23 14:06:51,350 DEBUG : Generating results file: ts_paint 14:06:51 INFO - 2015-10-23 14:06:51,350 DEBUG : Working with test: tpaint 14:06:51 INFO - 2015-10-23 14:06:51,350 DEBUG : Generating results file: tpaint 14:06:51 INFO - 2015-10-23 14:06:51,351 DEBUG : Working with test: sessionrestore 14:06:51 INFO - 2015-10-23 14:06:51,351 DEBUG : Generating results file: sessionrestore 14:06:51 INFO - 2015-10-23 14:06:51,351 DEBUG : Working with test: sessionrestore_no_auto_restore 14:06:51 INFO - 2015-10-23 14:06:51,351 DEBUG : Generating results file: sessionrestore_no_auto_restore 14:06:51 INFO - 2015-10-23 14:06:51,351 INFO : Posting result 0 of 5 to http://graphs.mozilla.org/server/collect.cgi, attempt 0 14:06:51 INFO - 2015-10-23 14:06:51,391 DEBUG : process_Request line: a11yr_paint graph.html#tests=[[223,64,55]] 14:06:51 INFO - 2015-10-23 14:06:51,391 DEBUG : process_Request line: a11yr_paint 545.45 graph.html#tests=[[223,64,55]] 14:06:51 INFO - 2015-10-23 14:06:51,391 INFO : Posting result 1 of 5 to http://graphs.mozilla.org/server/collect.cgi, attempt 0 14:06:51 INFO - 2015-10-23 14:06:51,449 DEBUG : process_Request line: ts_paint graph.html#tests=[[83,64,55]] 14:06:51 INFO - 2015-10-23 14:06:51,449 DEBUG : process_Request line: ts_paint 1287.98 graph.html#tests=[[83,64,55]] 14:06:51 INFO - 2015-10-23 14:06:51,449 INFO : Posting result 2 of 5 to http://graphs.mozilla.org/server/collect.cgi, attempt 0 14:06:51 INFO - 2015-10-23 14:06:51,491 DEBUG : process_Request line: tpaint graph.html#tests=[[82,64,55]] 14:06:51 INFO - 2015-10-23 14:06:51,491 DEBUG : process_Request line: tpaint 333.64 graph.html#tests=[[82,64,55]] 14:06:51 INFO - 2015-10-23 14:06:51,491 INFO : Posting result 3 of 5 to http://graphs.mozilla.org/server/collect.cgi, attempt 0 14:06:51 INFO - 2015-10-23 14:06:51,543 DEBUG : process_Request line: sessionrestore graph.html#tests=[[313,64,55]] 14:06:51 INFO - 2015-10-23 14:06:51,544 DEBUG : process_Request line: sessionrestore 2402.61 graph.html#tests=[[313,64,55]] 14:06:51 INFO - 2015-10-23 14:06:51,544 INFO : Posting result 4 of 5 to http://graphs.mozilla.org/server/collect.cgi, attempt 0 14:06:51 INFO - 2015-10-23 14:06:51,603 DEBUG : process_Request line: sessionrestore_no_auto_restore graph.html#tests=[[315,64,55]] 14:06:51 INFO - 2015-10-23 14:06:51,603 DEBUG : process_Request line: sessionrestore_no_auto_restore 1001.11 graph.html#tests=[[315,64,55]] 14:06:51 INFO - 2015-10-23 14:06:51,604 INFO : TALOSDATA: [{"talos_counters": {}, "results": {"dhtml.html": [1109.0, 1141.0, 1059.0, 1146.0, 1144.0, 1145.0, 1142.0, 1147.0, 1181.0, 1147.0, 1155.0, 1153.0, 1063.0, 1183.0, 1062.0, 1184.0, 1156.0, 1143.0, 1148.0, 1161.0, 1149.0, 1150.0, 1143.0, 1153.0, 1155.0], "tablemutation.html": [264.0, 262.0, 267.0, 258.0, 259.0, 260.0, 258.0, 259.0, 259.0, 257.0, 258.0, 259.0, 260.0, 259.0, 259.0, 259.0, 261.0, 261.0, 259.0, 259.0, 260.0, 259.0, 260.0, 259.0, 258.0]}, "summary": {"suite": 545.4521937004189, "subtests": {"dhtml.html": {"filtered": 1147.5, "value": 1147.5}, "tablemutation.html": {"filtered": 259.0, "value": 259.0}}}, "test_machine": {"platform": "x86_64", "osversion": "OS X 10.10.2", "os": "mac", "name": "t-yosemite-r5-0016"}, "testrun": {"date": 1445634148, "suite": "a11yr", "options": {"responsiveness": false, "tpmozafterpaint": true, "tpchrome": true, "tppagecycles": 25, "tpcycles": 1, "tprender": false, "shutdown": false, "cycles": 1, "rss": false}}, "test_build": {"name": "Firefox", "version": "44.0a1", "id": "20151023121232", "branch": "Fx-Team", "revision": "ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc"}}, {"talos_counters": {}, "results": {"ts_paint": [1714.0, 1264.0, 1270.0, 1260.0, 1261.0, 1267.0, 1270.0, 1255.0, 1264.0, 1264.0, 1288.0, 1269.0, 1261.0, 1291.0, 1271.0, 1291.0, 1266.0, 1260.0, 1269.0, 1266.0]}, "summary": {"suite": 1266.0, "subtests": {"ts_paint": {"filtered": 1266.0, "value": 1266.0}}}, "test_machine": {"platform": "x86_64", "osversion": "OS X 10.10.2", "os": "mac", "name": "t-yosemite-r5-0016"}, "testrun": {"date": 1445634148, "suite": "ts_paint", "options": {"responsiveness": false, "cycles": 20, "tpmozafterpaint": true, "shutdown": false, "rss": false}}, "test_build": {"name": "Firefox", "version": "44.0a1", "id": "20151023121232", "branch": "Fx-Team", "revision": "ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc"}}, {"talos_counters": {}, "results": {"tpaint": [308.40499999999975, 312.60000000000036, 314.58500000000004, 316.6750000000002, 317.3250000000007, 319.28500000000076, 324.3050000000003, 324.4150000000009, 326.16499999999905, 326.72000000000116, 327.2449999999999, 332.02999999999884, 333.6350000000002, 339.375, 342.7099999999991, 345.5099999999984, 359.58500000000276, 404.65500000000065, 405.5300000000025, 505.35000000000036]}, "summary": {"suite": 333.6350000000002, "subtests": {"tpaint": {"filtered": 333.6350000000002, "value": 333.6350000000002}}}, "test_machine": {"platform": "x86_64", "osversion": "OS X 10.10.2", "os": "mac", "name": "t-yosemite-r5-0016"}, "testrun": {"date": 1445634148, "suite": "tpaint", "options": {"responsiveness": false, "cycles": 1, "tpmozafterpaint": true, "shutdown": false, "rss": false}}, "test_build": {"name": "Firefox", "version": "44.0a1", "id": "20151023121232", "branch": "Fx-Team", "revision": "ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc"}}, {"talos_counters": {}, "results": {"sessionrestore": [2664.0, 2364.0, 2370.0, 2394.0, 2376.0, 2385.0, 2369.0, 2373.0, 2363.0, 2383.0]}, "summary": {"suite": 2373.0, "subtests": {"sessionrestore": {"filtered": 2373.0, "value": 2373.0}}}, "test_machine": {"platform": "x86_64", "osversion": "OS X 10.10.2", "os": "mac", "name": "t-yosemite-r5-0016"}, "testrun": {"date": 1445634148, "suite": "sessionrestore", "options": {"responsiveness": false, "cycles": 10, "tpmozafterpaint": false, "shutdown": false, "rss": false}}, "test_build": {"name": "Firefox", "version": "44.0a1", "id": "20151023121232", "branch": "Fx-Team", "revision": "ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc"}}, {"talos_counters": {}, "results": {"sessionrestore_no_auto_restore": [1278.0, 980.0, 972.0, 983.0, 965.0, 968.0, 970.0, 976.0, 982.0, 973.0]}, "summary": {"suite": 973.0, "subtests": {"sessionrestore_no_auto_restore": {"filtered": 973.0, "value": 973.0}}}, "test_machine": {"platform": "x86_64", "osversion": "OS X 10.10.2", "os": "mac", "name": "t-yosemite-r5-0016"}, "testrun": {"date": 1445634148, "suite": "sessionrestore_no_auto_restore", "options": {"responsiveness": false, "cycles": 10, "tpmozafterpaint": false, "shutdown": false, "rss": false}}, "test_build": {"name": "Firefox", "version": "44.0a1", "id": "20151023121232", "branch": "Fx-Team", "revision": "ccb7bb578fb15e0fe344b0e9a3b3628faed8bedc"}}] 14:06:51 INFO - RETURN: a11yr_paint: 545.45 14:06:51 INFO - RETURN: ts_paint: 1287.98 14:06:51 INFO - RETURN: tpaint: 333.64 14:06:51 INFO - RETURN: sessionrestore: 2402.61 14:06:51 INFO - RETURN: sessionrestore_no_auto_restore: 1001.11 14:06:51 INFO - TinderboxPrint: TalosResult: {"graphserver": {"sessionrestore": {"url": "http://graphs.mozilla.org/graph.html#tests=[[313,64,55]]", "result": "2402.61"}, "a11yr_paint": {"url": "http://graphs.mozilla.org/graph.html#tests=[[223,64,55]]", "result": "545.45"}, "tpaint": {"url": "http://graphs.mozilla.org/graph.html#tests=[[82,64,55]]", "result": "333.64"}, "ts_paint": {"url": "http://graphs.mozilla.org/graph.html#tests=[[83,64,55]]", "result": "1287.98"}, "sessionrestore_no_auto_restore": {"url": "http://graphs.mozilla.org/graph.html#tests=[[315,64,55]]", "result": "1001.11"}}} 14:06:51 INFO - Return code: 0 14:06:51 INFO - # TBPL SUCCESS # 14:06:51 INFO - Running pre test command check_screen_resolution with 'bash -c screenresolution get && screenresolution list && system_profiler SPDisplaysDataType' 14:06:51 INFO - Running command: ['bash', '-c', 'screenresolution get && screenresolution list && system_profiler SPDisplaysDataType'] in /builds/slave/test/build 14:06:51 INFO - Copy/paste: bash -c "screenresolution get && screenresolution list && system_profiler SPDisplaysDataType" 14:06:51 INFO - 2015-10-23 14:06:51.684 screenresolution[1697:12503] starting screenresolution argv=screenresolution get 14:06:51 INFO - 2015-10-23 14:06:51.687 screenresolution[1697:12503] Display 0: 1600x1200x32@60 14:06:51 INFO - 2015-10-23 14:06:51.693 screenresolution[1698:12505] starting screenresolution argv=screenresolution list 14:06:51 INFO - Available Modes on Display 0 14:06:51 INFO - 1600x1200x32@60 1152x870x32@75 1280x1024x32@75 14:06:51 INFO - 1024x768x32@75 1024x768x32@70 1024x768x32@60 14:06:51 INFO - 800x600x32@75 800x600x32@60 640x480x32@75 14:06:51 INFO - 640x480x32@60 1280x1024x32@60 1280x960x32@60 14:06:51 INFO - 1280x960x32@75 1344x1008x32@60 Graphics/Displays: 14:06:51 INFO - Intel HD Graphics 3000: 14:06:51 INFO - Chipset Model: Intel HD Graphics 3000 14:06:51 INFO - Type: GPU 14:06:51 INFO - Bus: Built-In 14:06:51 INFO - VRAM (Total): 512 MB 14:06:51 INFO - VRAM (Dynamic, Max): 10 14:06:51 INFO - Vendor: Intel (0x8086) 14:06:51 INFO - Device ID: 0x0116 14:06:51 INFO - Revision ID: 0x0009 14:06:51 INFO - Displays: 14:06:51 INFO - Display: 14:06:51 INFO - Resolution: 1600 x 1200 @ 60 Hz 14:06:51 INFO - Pixel Depth: 32-Bit Color (ARGB8888) 14:06:51 INFO - Display Serial Number: 1600x1200 60 14:06:51 INFO - Main Display: Yes 14:06:51 INFO - Mirror: Off 14:06:51 INFO - Online: Yes 14:06:51 INFO - Rotation: Supported 14:06:51 INFO - Return code: 0 14:06:51 INFO - Running post-action listener: _resource_record_post_action 14:06:51 INFO - Running post-run listener: _resource_record_post_run 14:06:52 INFO - Total resource usage - Wall time: 300s; CPU: 29.0%; Read bytes: 36234240; Write bytes: 595390464; Read time: 4155; Write time: 17720 14:06:52 INFO - install - Wall time: 36s; CPU: 30.0%; Read bytes: 337797632; Write bytes: 332773376; Read time: 31685; Write time: 3826 14:06:52 INFO - run-tests - Wall time: 264s; CPU: 29.0%; Read bytes: 34231296; Write bytes: 251484160; Read time: 3812; Write time: 12784 14:06:52 INFO - Running post-run listener: _upload_blobber_files 14:06:52 INFO - Blob upload gear active. 14:06:52 INFO - There are no files to upload in the directory. Skipping the blob upload mechanism ... 14:06:52 INFO - Copying logs to upload dir... 14:06:52 INFO - mkdir: /builds/slave/test/build/upload/logs program finished with exit code 0 elapsedTime=356.510944 ========= Finished '/tools/buildbot/bin/python scripts/scripts/talos_script.py ...' (results: 0, elapsed: 6 mins, 49 secs) (at 2015-10-23 14:07:45.786564) ========= ========= Started set props: build_url (results: 0, elapsed: 0 secs) (at 2015-10-23 14:07:45.790734) ========= 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: Apple_PubSub_Socket_Render=/private/tmp/com.apple.launchd.hzmkYpjbIV/Render GIT_SHARE_BASE_DIR=/builds/git-shared HG_SHARE_BASE_DIR=/builds/hg-shared HOME=/Users/cltbld IDLEIZER_DISABLE_SHUTDOWN=true LOGNAME=cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NO_EM_RESTART=1 PAGER=/bin/cat PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11 PWD=/builds/slave/test/properties RUNNER_CONFIG_CMD=/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg SHELL=/bin/bash SSH_AUTH_SOCK=/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners TMPDIR=/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/ TWISTD_LOG_PATH=/builds/slave/twistd.log USER=cltbld VERSIONER_PYTHON_PREFER_32_BIT=no VERSIONER_PYTHON_VERSION=2.7 XPCOM_DEBUG_BREAK=warn XPC_FLAGS=0x0 XPC_SERVICE_NAME=0 __CF_USER_TEXT_ENCODING=0x1C:0x0:0x0 using PTY: False build_url:https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.dmg program finished with exit code 0 elapsedTime=0.010183 build_url: 'https://queue.taskcluster.net/v1/task/kvTtorUhSAmyPm0bPMnhMA/artifacts/public/build/firefox-44.0a1.en-US.mac.dmg' ========= Finished set props: build_url (results: 0, elapsed: 0 secs) (at 2015-10-23 14:07:46.602164) ========= ========= Started 'rm -f ...' (results: 0, elapsed: 0 secs) (at 2015-10-23 14:07:46.605549) ========= rm -f oauth.txt in dir /builds/slave/test/. (timeout 1200 secs) watching logfiles {} argv: ['rm', '-f', 'oauth.txt'] environment: Apple_PubSub_Socket_Render=/private/tmp/com.apple.launchd.hzmkYpjbIV/Render GIT_SHARE_BASE_DIR=/builds/git-shared HG_SHARE_BASE_DIR=/builds/hg-shared HOME=/Users/cltbld IDLEIZER_DISABLE_SHUTDOWN=true LOGNAME=cltbld MOZ_CRASHREPORTER_NO_REPORT=1 MOZ_NO_REMOTE=1 NO_EM_RESTART=1 PAGER=/bin/cat PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/bin/X11 PWD=/builds/slave/test RUNNER_CONFIG_CMD=/opt/runner/bin/python2.7 /opt/runner/bin/runner -c /opt/runner/runner.cfg SHELL=/bin/bash SSH_AUTH_SOCK=/private/tmp/com.apple.launchd.OlDG3iec1b/Listeners TMPDIR=/var/folders/gg/q6y1_2717rsgmjth6gwwvht800000w/T/ TWISTD_LOG_PATH=/builds/slave/twistd.log USER=cltbld VERSIONER_PYTHON_PREFER_32_BIT=no VERSIONER_PYTHON_VERSION=2.7 XPCOM_DEBUG_BREAK=warn XPC_FLAGS=0x0 XPC_SERVICE_NAME=0 __CF_USER_TEXT_ENCODING=0x1C:0x0:0x0 using PTY: False program finished with exit code 0 elapsedTime=0.005468 ========= Finished 'rm -f ...' (results: 0, elapsed: 0 secs) (at 2015-10-23 14:07:46.691324) ========= ========= Started reboot slave lost (results: 0, elapsed: 26 secs) (at 2015-10-23 14:07:46.691834) ========= ========= Finished reboot slave lost (results: 0, elapsed: 26 secs) (at 2015-10-23 14:08:13.350332) =========