Filed by: aiakab [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=198663174&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/LiGzmvauRTa1jOobFujS8w/runs/0/artifacts/public/logs/live_backing.log [task 2018-09-11T15:56:30.407Z] 15:56:30 INFO - STDOUT: PASSED [task 2018-09-11T15:56:30.408Z] 15:56:30 INFO - PID 15773 | 1536681390400 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"9712f80b-aad2-4c76-b73d-e18ea8f1d122","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"64.0a1","moz:accessibilityChecks":false,"moz:geckodriverVersion":"0.21.0","moz:headless":false,"moz:processID":24362,"moz:profile":"/tmp/rust_mozprofile.udHz7J6ZwLdy","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"linux","platformVersion":"4.4.0-1014-aws","rotatable":false,"setWindowRect":true,"test:extension":{"key":"value"},"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}} [task 2018-09-11T15:56:30.408Z] 15:56:30 INFO - PID 15773 | 1536681390403 webdriver::server DEBUG -> DELETE /session/9712f80b-aad2-4c76-b73d-e18ea8f1d122 [task 2018-09-11T15:56:30.417Z] 15:56:30 INFO - PID 15773 | 1536681390408 Marionette TRACE 0 -> [0,2,"Marionette:Quit",{"flags":["eForceQuit"]}] [task 2018-09-11T15:56:30.417Z] 15:56:30 INFO - PID 15773 | 1536681390411 Marionette INFO Stopped listening on port 2828 [task 2018-09-11T15:56:30.543Z] 15:56:30 INFO - PID 15773 | 1536681390540 Marionette TRACE 0 <- [1,2,null,{"cause":"shutdown"}] [task 2018-09-11T15:56:30.633Z] 15:56:30 INFO - PID 15773 | 1536681390626 webdriver::server DEBUG Deleting session [task 2018-09-11T15:56:30.642Z] 15:56:30 INFO - PID 15773 | 1536681390636 Marionette TRACE 0 -> [0,3,"Marionette:Quit",{"flags":["eForceQuit"]}] [task 2018-09-11T15:56:30.643Z] 15:56:30 INFO - PID 15773 | 1536681390638 Marionette TRACE 0 <- [1,3,{"error":"invalid session id","message":"Tried to run command without establishing a connection","stacktrace":"WebDriver ... et@chrome://marionette/content/server.js:245:8\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:490:9\n"},null] [task 2018-09-11T15:56:30.705Z] 15:56:30 INFO - PID 15773 | 1536681390698 Marionette DEBUG Closed connection 0 [task 2018-09-11T15:56:30.926Z] 15:56:30 INFO - PID 15773 | JavaScript error: jar:file:///builds/worker/workspace/build/application/firefox/omni.ja!/components/nsUrlClassifierListManager.js, line 329: NS_ERROR_NOT_INITIALIZED: Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIUrlClassifierDBService.getTables] [task 2018-09-11T15:56:30.927Z] 15:56:30 INFO - PID 15773 | JavaScript error: jar:file:///builds/worker/workspace/build/application/firefox/omni.ja!/components/nsUrlClassifierListManager.js, line 329: NS_ERROR_NOT_INITIALIZED: Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIUrlClassifierDBService.getTables] [task 2018-09-11T15:56:31.327Z] 15:56:31 INFO - PID 15773 | 1536681391314 Marionette DEBUG Received observer notification xpcom-will-shutdown [task 2018-09-11T15:56:31.328Z] 15:56:31 INFO - PID 15773 | 1536681391314 Marionette DEBUG Resetting recommended pref security.turn_off_all_security_so_that_viruses_can_take_over_this_computer [task 2018-09-11T15:56:31.329Z] 15:56:31 INFO - PID 15773 | 1536681391314 Marionette DEBUG Resetting recommended pref apz.content_response_timeout [task 2018-09-11T15:56:31.329Z] 15:56:31 INFO - PID 15773 | 1536681391315 Marionette DEBUG Resetting recommended pref browser.download.panel.shown [task 2018-09-11T15:56:31.330Z] 15:56:31 INFO - PID 15773 | 1536681391315 Marionette DEBUG Resetting recommended pref browser.pagethumbnails.capturing_disabled [task 2018-09-11T15:56:31.330Z] 15:56:31 INFO - PID 15773 | 1536681391315 Marionette DEBUG Resetting recommended pref browser.search.update [task 2018-09-11T15:56:31.331Z] 15:56:31 INFO - PID 15773 | 1536681391315 Marionette DEBUG Resetting recommended pref toolkit.cosmeticAnimations.enabled [task 2018-09-11T15:56:31.332Z] 15:56:31 INFO - PID 15773 | 1536681391317 Marionette DEBUG Resetting recommended pref browser.tabs.disableBackgroundZombification [task 2018-09-11T15:56:31.333Z] 15:56:31 INFO - PID 15773 | 1536681391317 Marionette DEBUG Resetting recommended pref browser.tabs.warnOnCloseOtherTabs [task 2018-09-11T15:56:31.334Z] 15:56:31 INFO - PID 15773 | 1536681391317 Marionette DEBUG Resetting recommended pref browser.tabs.warnOnOpen [task 2018-09-11T15:56:31.334Z] 15:56:31 INFO - PID 15773 | 1536681391318 Marionette DEBUG Resetting recommended pref browser.usedOnWindows10.introURL [task 2018-09-11T15:56:31.335Z] 15:56:31 INFO - PID 15773 | 1536681391318 Marionette DEBUG Resetting recommended pref browser.urlbar.suggest.searches [task 2018-09-11T15:56:31.335Z] 15:56:31 INFO - PID 15773 | 1536681391320 Marionette DEBUG Resetting recommended pref datareporting.policy.dataSubmissionPolicyAccepted [task 2018-09-11T15:56:31.336Z] 15:56:31 INFO - PID 15773 | 1536681391320 Marionette DEBUG Resetting recommended pref dom.disable_beforeunload [task 2018-09-11T15:56:31.341Z] 15:56:31 INFO - PID 15773 | 1536681391321 Marionette DEBUG Resetting recommended pref dom.disable_open_during_load [task 2018-09-11T15:56:31.343Z] 15:56:31 INFO - PID 15773 | 1536681391321 Marionette DEBUG Resetting recommended pref dom.file.createInChild [task 2018-09-11T15:56:31.345Z] 15:56:31 INFO - PID 15773 | 1536681391321 Marionette DEBUG Resetting recommended pref dom.max_chrome_script_run_time [task 2018-09-11T15:56:31.348Z] 15:56:31 INFO - PID 15773 | 1536681391326 Marionette DEBUG Resetting recommended pref dom.max_script_run_time [task 2018-09-11T15:56:31.349Z] 15:56:31 INFO - PID 15773 | 1536681391333 Marionette DEBUG Resetting recommended pref extensions.getAddons.cache.enabled [task 2018-09-11T15:56:31.350Z] 15:56:31 INFO - PID 15773 | 1536681391333 Marionette DEBUG Resetting recommended pref extensions.webservice.discoverURL [task 2018-09-11T15:56:31.353Z] 15:56:31 INFO - PID 15773 | 1536681391334 Marionette DEBUG Resetting recommended pref network.http.prompt-temp-redirect [task 2018-09-11T15:56:31.354Z] 15:56:31 INFO - PID 15773 | 1536681391334 Marionette DEBUG Resetting recommended pref network.http.speculative-parallel-limit [task 2018-09-11T15:56:31.355Z] 15:56:31 INFO - PID 15773 | 1536681391334 Marionette DEBUG Resetting recommended pref security.fileuri.strict_origin_policy [task 2018-09-11T15:56:31.356Z] 15:56:31 INFO - PID 15773 | 1536681391334 Marionette DEBUG Resetting recommended pref security.notification_enable_delay [task 2018-09-11T15:56:31.358Z] 15:56:31 INFO - PID 15773 | 1536681391335 Marionette DEBUG Resetting recommended pref signon.autofillForms [task 2018-09-11T15:56:31.358Z] 15:56:31 INFO - PID 15773 | 1536681391335 Marionette DEBUG Resetting recommended pref signon.rememberSignons [task 2018-09-11T15:56:31.358Z] 15:56:31 INFO - PID 15773 | 1536681391337 Marionette DEBUG Remote service is inactive [task 2018-09-11T15:56:31.377Z] 15:56:31 INFO - PID 15773 | JavaScript error: resource://gre/modules/osfile/osfile_async_front.jsm, line 407: Error: OS.File has been shut down. Rejecting post to DirectoryIterator_prototype_close [task 2018-09-11T15:56:31.377Z] 15:56:31 INFO - PID 15773 | JavaScript error: resource://gre/modules/ProfileAge.jsm, line 197: Error: Unable to fetch oldest profile entry: Error: OS.File has been shut down. Rejecting request to DirectoryIterator_prototype_next [task 2018-09-11T15:56:31.379Z] 15:56:31 INFO - PID 15773 | JavaScript error: resource://gre/modules/osfile/osfile_async_front.jsm, line 407: Error: OS.File has been shut down. Rejecting post to DirectoryIterator_prototype_close [task 2018-09-11T15:56:31.379Z] 15:56:31 INFO - PID 15773 | JavaScript error: resource://gre/modules/ProfileAge.jsm, line 197: Error: Unable to fetch oldest profile entry: Error: OS.File has been shut down. Rejecting post to DirectoryIterator_prototype_next [task 2018-09-11T15:56:32.357Z] 15:56:32 INFO - STDOUT: =================================== FAILURES =================================== [task 2018-09-11T15:56:32.358Z] 15:56:32 INFO - STDOUT: ______________________ test_valid[pageLoadStrategy-none] _______________________ [task 2018-09-11T15:56:32.358Z] 15:56:32 INFO - STDOUT: new_session = <function new_session at 0x7fa2ed5539b0> [task 2018-09-11T15:56:32.359Z] 15:56:32 INFO - STDOUT: add_browser_capabilities = <function add_browser_capabilities at 0x7fa2ed553938> [task 2018-09-11T15:56:32.359Z] 15:56:32 INFO - STDOUT: key = 'pageLoadStrategy', value = 'none' [task 2018-09-11T15:56:32.360Z] 15:56:32 INFO - STDOUT: @pytest.mark.parametrize("key,value", flatten(product(*item) for item in valid_data)) [task 2018-09-11T15:56:32.360Z] 15:56:32 INFO - STDOUT: def test_valid(new_session, add_browser_capabilities, key, value): [task 2018-09-11T15:56:32.361Z] 15:56:32 INFO - STDOUT: response, _ = new_session({"capabilities": { [task 2018-09-11T15:56:32.361Z] 15:56:32 INFO - STDOUT: "firstMatch": [add_browser_capabilities({key: value})]}}) [task 2018-09-11T15:56:32.361Z] 15:56:32 INFO - STDOUT: > assert_success(response) [task 2018-09-11T15:56:32.362Z] 15:56:32 INFO - STDOUT: _ = None [task 2018-09-11T15:56:32.362Z] 15:56:32 INFO - STDOUT: add_browser_capabilities = <function add_browser_capabilities at 0x7fa2ed553938> [task 2018-09-11T15:56:32.363Z] 15:56:32 INFO - STDOUT: key = 'pageLoadStrategy' [task 2018-09-11T15:56:32.363Z] 15:56:32 INFO - STDOUT: new_session = <function new_session at 0x7fa2ed5539b0> [task 2018-09-11T15:56:32.364Z] 15:56:32 INFO - STDOUT: response = <Response status=500 error=<UnknownErrorException http_status=500>> [task 2018-09-11T15:56:32.364Z] 15:56:32 INFO - STDOUT: value = 'none' [task 2018-09-11T15:56:32.364Z] 15:56:32 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py [task 2018-09-11T15:56:32.365Z] 15:56:32 INFO - STDOUT: :16: [task 2018-09-11T15:56:32.365Z] 15:56:32 INFO - STDOUT: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ [task 2018-09-11T15:56:32.366Z] 15:56:32 INFO - STDOUT: response = <Response status=500 error=<UnknownErrorException http_status=500>> [task 2018-09-11T15:56:32.366Z] 15:56:32 INFO - STDOUT: value = None [task 2018-09-11T15:56:32.367Z] 15:56:32 INFO - STDOUT: def assert_success(response, value=None): [task 2018-09-11T15:56:32.367Z] 15:56:32 INFO - STDOUT: """ [task 2018-09-11T15:56:32.368Z] 15:56:32 INFO - STDOUT: Verify that the provided webdriver.Response instance described [task 2018-09-11T15:56:32.368Z] 15:56:32 INFO - STDOUT: a valid error response as defined by `dfn-send-an-error` and [task 2018-09-11T15:56:32.369Z] 15:56:32 INFO - STDOUT: the provided error code. [task 2018-09-11T15:56:32.369Z] 15:56:32 INFO - STDOUT: [task 2018-09-11T15:56:32.370Z] 15:56:32 INFO - STDOUT: :param response: ``webdriver.Response`` instance. [task 2018-09-11T15:56:32.370Z] 15:56:32 INFO - STDOUT: :param value: Expected value of the response body, if any. [task 2018-09-11T15:56:32.370Z] 15:56:32 INFO - STDOUT: """ [task 2018-09-11T15:56:32.371Z] 15:56:32 INFO - STDOUT: > assert response.status == 200, str(response.error) [task 2018-09-11T15:56:32.371Z] 15:56:32 INFO - STDOUT: E AssertionError: unknown error (500): connection refused [task 2018-09-11T15:56:32.371Z] 15:56:32 INFO - STDOUT: E [task 2018-09-11T15:56:32.373Z] 15:56:32 INFO - STDOUT: E assert 500 == 200 [task 2018-09-11T15:56:32.373Z] 15:56:32 INFO - STDOUT: E + where 500 = <Response status=500 error=<UnknownErrorException http_status=500>>.status [task 2018-09-11T15:56:32.374Z] 15:56:32 INFO - STDOUT: response = <Response status=500 error=<UnknownErrorException http_status=500>> [task 2018-09-11T15:56:32.374Z] 15:56:32 INFO - STDOUT: value = None [task 2018-09-11T15:56:32.375Z] 15:56:32 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/support/asserts.py [task 2018-09-11T15:56:32.375Z] 15:56:32 INFO - STDOUT: :62: AssertionError [task 2018-09-11T15:56:32.375Z] 15:56:32 INFO - STDOUT: =============================== warnings summary =============================== [task 2018-09-11T15:56:32.376Z] 15:56:32 INFO - STDOUT: <undetermined location> [task 2018-09-11T15:56:32.376Z] 15:56:32 INFO - STDOUT: Module already imported so cannot be rewritten: mozlog [task 2018-09-11T15:56:32.377Z] 15:56:32 INFO - STDOUT: -- Docs: http://doc.pytest.org/en/latest/warnings.html [task 2018-09-11T15:56:32.378Z] 15:56:32 INFO - STDOUT: ============== 1 failed, 23 passed, 1 warnings in 257.51 seconds =============== [task 2018-09-11T15:56:32.378Z] 15:56:32 INFO - PID 15773 | 1536681392346 geckodriver::marionette DEBUG Browser process stopped: exit code: 0 [task 2018-09-11T15:56:32.379Z] 15:56:32 INFO - PID 15773 | 1536681392349 webdriver::server DEBUG <- 200 OK {"value":null} [task 2018-09-11T15:56:32.396Z] 15:56:32 INFO - [task 2018-09-11T15:56:32.396Z] 15:56:32 INFO - TEST-PASS | /webdriver/tests/new_session/create_firstMatch.py | test_valid[acceptInsecureCerts-False] [task 2018-09-11T15:56:32.397Z] 15:56:32 INFO - TEST-PASS | /webdriver/tests/new_session/create_firstMatch.py | test_valid[acceptInsecureCerts-None] [task 2018-09-11T15:56:32.398Z] 15:56:32 INFO - TEST-PASS | /webdriver/tests/new_session/create_firstMatch.py | test_valid[browserName-None] [task 2018-09-11T15:56:32.399Z] 15:56:32 INFO - TEST-PASS | /webdriver/tests/new_session/create_firstMatch.py | test_valid[browserVersion-None] [task 2018-09-11T15:56:32.399Z] 15:56:32 INFO - TEST-PASS | /webdriver/tests/new_session/create_firstMatch.py | test_valid[platformName-None] [task 2018-09-11T15:56:32.400Z] 15:56:32 INFO - TEST-PASS | /webdriver/tests/new_session/create_firstMatch.py | test_valid[pageLoadStrategy-None] [task 2018-09-11T15:56:32.400Z] 15:56:32 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/new_session/create_firstMatch.py | test_valid[pageLoadStrategy-none] - AssertionError: unknown error (500): connection refused [task 2018-09-11T15:56:32.400Z] 15:56:32 INFO - new_session = <function new_session at 0x7fa2ed5539b0> [task 2018-09-11T15:56:32.405Z] 15:56:32 INFO - add_browser_capabilities = <function add_browser_capabilities at 0x7fa2ed553938> [task 2018-09-11T15:56:32.405Z] 15:56:32 INFO - key = 'pageLoadStrategy', value = 'none' [task 2018-09-11T15:56:32.406Z] 15:56:32 INFO - [task 2018-09-11T15:56:32.407Z] 15:56:32 INFO - @pytest.mark.parametrize("key,value", flatten(product(*item) for item in valid_data)) [task 2018-09-11T15:56:32.408Z] 15:56:32 INFO - def test_valid(new_session, add_browser_capabilities, key, value): [task 2018-09-11T15:56:32.410Z] 15:56:32 INFO - response, _ = new_session({"capabilities": { [task 2018-09-11T15:56:32.411Z] 15:56:32 INFO - "firstMatch": [add_browser_capabilities({key: value})]}}) [task 2018-09-11T15:56:32.412Z] 15:56:32 INFO - > assert_success(response) [task 2018-09-11T15:56:32.413Z] 15:56:32 INFO - [task 2018-09-11T15:56:32.414Z] 15:56:32 INFO - _ = None [task 2018-09-11T15:56:32.414Z] 15:56:32 INFO - add_browser_capabilities = <function add_browser_capabilities at 0x7fa2ed553938> [task 2018-09-11T15:56:32.414Z] 15:56:32 INFO - key = 'pageLoadStrategy' [task 2018-09-11T15:56:32.414Z] 15:56:32 INFO - new_session = <function new_session at 0x7fa2ed5539b0> [task 2018-09-11T15:56:32.415Z] 15:56:32 INFO - response = <Response status=500 error=<UnknownErrorException http_status=500>> [task 2018-09-11T15:56:32.415Z] 15:56:32 INFO - value = 'none' [task 2018-09-11T15:56:32.415Z] 15:56:32 INFO - [task 2018-09-11T15:56:32.415Z] 15:56:32 INFO - tests/web-platform/tests/webdriver/tests/new_session/create_firstMatch.py:16: [task 2018-09-11T15:56:32.415Z] 15:56:32 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ [task 2018-09-11T15:56:32.415Z] 15:56:32 INFO - [task 2018-09-11T15:56:32.415Z] 15:56:32 INFO - response = <Response status=500 error=<UnknownErrorException http_status=500>> [task 2018-09-11T15:56:32.416Z] 15:56:32 INFO - value = None [task 2018-09-11T15:56:32.416Z] 15:56:32 INFO - [task 2018-09-11T15:56:32.416Z] 15:56:32 INFO - def assert_success(response, value=None): [task 2018-09-11T15:56:32.416Z] 15:56:32 INFO - """ [task 2018-09-11T15:56:32.416Z] 15:56:32 INFO - Verify that the provided webdriver.Response instance described [task 2018-09-11T15:56:32.417Z] 15:56:32 INFO - a valid error response as defined by `dfn-send-an-error` and [task 2018-09-11T15:56:32.417Z] 15:56:32 INFO - the provided error code. [task 2018-09-11T15:56:32.417Z] 15:56:32 INFO - [task 2018-09-11T15:56:32.417Z] 15:56:32 INFO - :param response: ``webdriver.Response`` instance. [task 2018-09-11T15:56:32.418Z] 15:56:32 INFO - :param value: Expected value of the response body, if any. [task 2018-09-11T15:56:32.418Z] 15:56:32 INFO - """ [task 2018-09-11T15:56:32.418Z] 15:56:32 INFO - > assert response.status == 200, str(response.error) [task 2018-09-11T15:56:32.418Z] 15:56:32 INFO - E AssertionError: unknown error (500): connection refused [task 2018-09-11T15:56:32.418Z] 15:56:32 INFO - E [task 2018-09-11T15:56:32.419Z] 15:56:32 INFO - E assert 500 == 200 [task 2018-09-11T15:56:32.419Z] 15:56:32 INFO - E + where 500 = <Response status=500 error=<UnknownErrorException http_status=500>>.status [task 2018-09-11T15:56:32.419Z] 15:56:32 INFO - [task 2018-09-11T15:56:32.419Z] 15:56:32 INFO - response = <Response status=500 error=<UnknownErrorException http_status=500>> [task 2018-09-11T15:56:32.419Z] 15:56:32 INFO - value = None [task 2018-09-11T15:56:32.419Z] 15:56:32 INFO - [task 2018-09-11T15:56:32.419Z] 15:56:32 INFO - tests/web-platform/tests/webdriver/tests/support/asserts.py:62: AssertionError [task 2018-09-11T15:56:32.424Z] 15:56:32 INFO - ................. [task 2018-09-11T15:56:32.424Z] 15:56:32 INFO - TEST-OK | /webdriver/tests/new_session/create_firstMatch.py | took 257582ms [task 2018-09-11T15:56:32.478Z] 15:56:32 WARNING - u'runner_teardown': ()

It's a hang during startup for an Firefox ASAN build on Linux64. So this depends on bug 1487243.

While the ASAN part is fixed for this failure, there was also a crash on MacOS happening. See the last failure comment from the Intermittent Failures Robot. Given that we don't analyze crash reports yet, I cannot say why it crashed.

Moving bug to Remote Protocol::Marionette component per bug 1815831.