Closed Bug 1548426 Opened 5 years ago Closed 2 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/response.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 1630162

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, regression)

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=244047811&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/KD6emLDwSx-tA14qpFBuyw/runs/0/artifacts/public/logs/live_backing.log


[task 2019-05-02T00:10:58.267Z] 00:10:58 INFO - TEST-START | /webdriver/tests/new_session/response.py
[task 2019-05-02T00:10:58.303Z] 00:10:58 INFO - STDOUT: ============================= test session starts ==============================
[task 2019-05-02T00:10:58.304Z] 00:10:58 INFO - STDOUT: platform linux2 -- Python 2.7.12, pytest-unknown, py-1.5.2, pluggy-0.5.3.dev -- /builds/worker/workspace/build/venv/bin/python
[task 2019-05-02T00:10:58.304Z] 00:10:58 INFO - STDOUT: rootdir: /builds/worker/workspace/build, inifile:
[task 2019-05-02T00:10:58.304Z] 00:10:58 INFO - STDOUT: collecting ...
[task 2019-05-02T00:10:58.408Z] 00:10:58 INFO - STDOUT: collected 18 items
[task 2019-05-02T00:10:58.408Z] 00:10:58 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/response.py::test_sessionid
[task 2019-05-02T00:10:58.424Z] 00:10:58 INFO - PID 26279 | 1556755858408 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"binary": "/builds/worker/workspace/build/application/firefox/firefox", "prefs": {"network.dns.localDomains": "www1.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www1.web-platform.test,www.www2.not-web-platform.test,www2.www2.not-web-platform.test,xn--lve-6lad.www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.not-web-platform.test,not-web-platform.test,www1.www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.web-platform.test,www2.not-web-platform.test,www1.not-web-platform.test,www1.www1.web-platform.test,www2.xn--lve-6lad.web-platform.test,www1.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www1.www2.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.not-web-platform.test,www2.www1.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.not-web-platform.test,xn--lve-6lad.www.web-platform.test,www.www.web-platform.test,www1.xn--lve-6lad.web-platform.test,xn--lve-6lad.www2.web-platform.test,www.www2.web-platform.test,www2.www.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.not-web-platform.test,www1.www.web-platform.test,www.xn--lve-6lad.web-platform.test,www.www.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.web-platform.test,xn--lve-6lad.www1.not-web-platform.test,www1.www1.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.not-web-platform.test,www2.www2.web-platform.test,xn--lve-6lad.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.web-platform.test,xn--lve-6lad.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,www2.xn--lve-6lad.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.web-platform.test,www1.xn--lve-6lad.not-web-platform.test,www1.web-platform.test,www.www1.web-platform.test,www2.web-platform.test,www.xn--lve-6lad.not-web-platform.test,www.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www1.www2.not-web-platform.test,www2.www1.web-platform.test,www.www1.not-web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test"}}}}}
[task 2019-05-02T00:10:58.425Z] 00:10:58 INFO - PID 26279 | 1556755858410 mozrunner::runner INFO Running command: "/builds/worker/workspace/build/application/firefox/firefox" "-marionette" "-foreground" "-no-remote" "-profile" "/tmp/rust_mozprofile.5koqj9SaelF5"
[task 2019-05-02T00:10:58.425Z] 00:10:58 INFO - PID 26279 | 1556755858410 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1:2828
[task 2019-05-02T00:10:59.087Z] 00:10:59 INFO - PID 26279 | 1556755859083 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: mozillaAddons
[task 2019-05-02T00:10:59.087Z] 00:10:59 INFO - PID 26279 | 1556755859083 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: resource://pdf.js/
[task 2019-05-02T00:10:59.088Z] 00:10:59 INFO - PID 26279 | 1556755859083 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: about:reader*
[task 2019-05-02T00:10:59.230Z] 00:10:59 INFO - PID 26279 | 1556755859228 Marionette TRACE Received observer notification profile-after-change
[task 2019-05-02T00:10:59.266Z] 00:10:59 INFO - PID 26279 | 1556755859258 Marionette TRACE Received observer notification command-line-startup
[task 2019-05-02T00:10:59.268Z] 00:10:59 INFO - PID 26279 | 1556755859258 Marionette TRACE Received observer notification nsPref:changed
[task 2019-05-02T00:10:59.268Z] 00:10:59 INFO - PID 26279 | 1556755859258 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
[task 2019-05-02T00:10:59.800Z] 00:10:59 INFO - PID 26279 | 1556755859795 Marionette TRACE Received observer notification toplevel-window-ready
[task 2019-05-02T00:11:02.747Z] 00:11:02 INFO - PID 26279 | 1556755862740 Marionette TRACE Received observer notification marionette-startup-requested
[task 2019-05-02T00:11:02.748Z] 00:11:02 INFO - PID 26279 | 1556755862740 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2019-05-02T00:11:02.837Z] 00:11:02 INFO - PID 26279 | 1556755862827 Marionette TRACE All scripts recorded.
[task 2019-05-02T00:11:02.837Z] 00:11:02 INFO - PID 26279 | 1556755862828 Marionette DEBUG Setting recommended pref apz.content_response_timeout to 60000
[task 2019-05-02T00:11:02.839Z] 00:11:02 INFO - PID 26279 | 1556755862828 Marionette DEBUG Setting recommended pref browser.contentblocking.introCount to 99
[task 2019-05-02T00:11:02.842Z] 00:11:02 INFO - PID 26279 | 1556755862828 Marionette DEBUG Setting recommended pref browser.download.panel.shown to true
[task 2019-05-02T00:11:02.842Z] 00:11:02 INFO - PID 26279 | 1556755862829 Marionette DEBUG Setting recommended pref browser.newtabpage.enabled to false
[task 2019-05-02T00:11:02.842Z] 00:11:02 INFO - PID 26279 | 1556755862830 Marionette DEBUG Setting recommended pref browser.pagethumbnails.capturing_disabled to true
[task 2019-05-02T00:11:02.844Z] 00:11:02 INFO - PID 26279 | 1556755862830 Marionette DEBUG Setting recommended pref browser.search.update to false
[task 2019-05-02T00:11:02.844Z] 00:11:02 INFO - PID 26279 | 1556755862831 Marionette DEBUG Setting recommended pref browser.tabs.disableBackgroundZombification to false
[task 2019-05-02T00:11:02.845Z] 00:11:02 INFO - PID 26279 | 1556755862831 Marionette DEBUG Setting recommended pref browser.tabs.warnOnCloseOtherTabs to false
[task 2019-05-02T00:11:02.847Z] 00:11:02 INFO - PID 26279 | 1556755862831 Marionette DEBUG Setting recommended pref browser.tabs.warnOnOpen to false
[task 2019-05-02T00:11:02.848Z] 00:11:02 INFO - PID 26279 | 1556755862832 Marionette DEBUG Setting recommended pref browser.usedOnWindows10.introURL to
[task 2019-05-02T00:11:02.848Z] 00:11:02 INFO - PID 26279 | 1556755862832 Marionette DEBUG Setting recommended pref browser.urlbar.suggest.searches to false
[task 2019-05-02T00:11:02.849Z] 00:11:02 INFO - PID 26279 | 1556755862834 Marionette DEBUG Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
[task 2019-05-02T00:11:02.850Z] 00:11:02 INFO - PID 26279 | 1556755862834 Marionette DEBUG Setting recommended pref dom.disable_beforeunload to true
[task 2019-05-02T00:11:02.850Z] 00:11:02 INFO - PID 26279 | 1556755862834 Marionette DEBUG Setting recommended pref dom.disable_open_during_load to false
[task 2019-05-02T00:11:02.852Z] 00:11:02 INFO - PID 26279 | 1556755862834 Marionette DEBUG Setting recommended pref dom.file.createInChild to true
[task 2019-05-02T00:11:02.853Z] 00:11:02 INFO - PID 26279 | 1556755862835 Marionette DEBUG Setting recommended pref dom.max_chrome_script_run_time to 0
[task 2019-05-02T00:11:02.854Z] 00:11:02 INFO - PID 26279 | 1556755862835 Marionette DEBUG Setting recommended pref dom.max_script_run_time to 0
[task 2019-05-02T00:11:02.854Z] 00:11:02 INFO - PID 26279 | 1556755862836 Marionette DEBUG Setting recommended pref extensions.getAddons.cache.enabled to false
[task 2019-05-02T00:11:02.855Z] 00:11:02 INFO - PID 26279 | 1556755862836 Marionette DEBUG Setting recommended pref extensions.webservice.discoverURL to http://%(server)s/dummy/discoveryURL
[task 2019-05-02T00:11:02.857Z] 00:11:02 INFO - PID 26279 | 1556755862838 Marionette DEBUG Setting recommended pref network.http.prompt-temp-redirect to false
[task 2019-05-02T00:11:02.857Z] 00:11:02 INFO - PID 26279 | 1556755862838 Marionette DEBUG Setting recommended pref network.http.speculative-parallel-limit to 0
[task 2019-05-02T00:11:02.858Z] 00:11:02 INFO - PID 26279 | 1556755862838 Marionette DEBUG Setting recommended pref security.fileuri.strict_origin_policy to false
[task 2019-05-02T00:11:02.860Z] 00:11:02 INFO - PID 26279 | 1556755862839 Marionette DEBUG Setting recommended pref security.notification_enable_delay to 0
[task 2019-05-02T00:11:02.860Z] 00:11:02 INFO - PID 26279 | 1556755862841 Marionette DEBUG Setting recommended pref signon.autofillForms to false
[task 2019-05-02T00:11:02.861Z] 00:11:02 INFO - PID 26279 | 1556755862841 Marionette DEBUG Setting recommended pref signon.rememberSignons to false
[task 2019-05-02T00:11:02.861Z] 00:11:02 INFO - PID 26279 | 1556755862842 Marionette DEBUG Setting recommended pref toolkit.cosmeticAnimations.enabled to false
[task 2019-05-02T00:11:02.902Z] 00:11:02 INFO - PID 26279 | 1556755862898 Marionette INFO Listening on port 2828
[task 2019-05-02T00:11:02.903Z] 00:11:02 INFO - PID 26279 | 1556755862898 Marionette DEBUG Remote service is active
[task 2019-05-02T00:11:02.923Z] 00:11:02 INFO - PID 26279 | 1556755862921 geckodriver::marionette DEBUG Connection established on 127.0.0.1:2828. Waiting for Marionette handshake
[task 2019-05-02T00:11:02.939Z] 00:11:02 INFO - PID 26279 | 1556755862935 Marionette DEBUG Accepted connection 0 from 127.0.0.1:35388
[task 2019-05-02T00:11:02.941Z] 00:11:02 INFO - PID 26279 | 1556755862937 geckodriver::marionette DEBUG Connected to Marionette
[task 2019-05-02T00:11:02.949Z] 00:11:02 INFO - PID 26279 | 1556755862938 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{}]
[task 2019-05-02T00:11:03.000Z] 00:11:02 INFO - PID 26279 | 1556755862964 Marionette TRACE [4294967297] Frame script loaded
[task 2019-05-02T00:11:03.000Z] 00:11:03 INFO - PID 26279 | 1556755862965 Marionette TRACE [4294967297] Frame script registered
[task 2019-05-02T00:11:03.002Z] 00:11:03 INFO - PID 26279 | 1556755862970 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"026d6279-82eb-4532-8b8b-9a6dd1acf83e","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... ozprofile.5koqj9SaelF5","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-05-02T00:11:03.002Z] 00:11:03 INFO - STDOUT: PASSED
[task 2019-05-02T00:11:03.003Z] 00:11:03 INFO - PID 26279 | 1556755862972 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"026d6279-82eb-4532-8b8b-9a6dd1acf83e","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"68.0a1","moz:accessibilityChecks":false,"moz:buildID":"20190501215533","moz:geckodriverVersion":"0.24.0","moz:headless":false,"moz:processID":28832,"moz:profile":"/tmp/rust_mozprofile.5koqj9SaelF5","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"linux","platformVersion":"4.4.0-1014-aws","rotatable":false,"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2019-05-02T00:11:03.005Z] 00:11:03 INFO - PID 26279 | 1556755862975 webdriver::server DEBUG -> DELETE /session/026d6279-82eb-4532-8b8b-9a6dd1acf83e
[task 2019-05-02T00:11:03.005Z] 00:11:03 INFO - PID 26279 | 1556755862976 Marionette DEBUG 0 -> [0,2,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2019-05-02T00:11:03.006Z] 00:11:03 INFO - PID 26279 | 1556755862977 Marionette INFO Stopped listening on port 2828
[task 2019-05-02T00:11:03.006Z] 00:11:03 INFO - PID 26279 | JavaScript error: resource://activity-stream/lib/ActivityStreamPrefs.jsm, line 23: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIPrefBranch.removeObserver]
[task 2019-05-02T00:11:03.025Z] 00:11:03 INFO - PID 26279 | 1556755863021 Marionette TRACE Received observer notification quit-application
[task 2019-05-02T00:11:03.033Z] 00:11:03 INFO - PID 26279 | 1556755863027 Marionette DEBUG 0 <- [1,2,null,{"cause":"shutdown"}]
[task 2019-05-02T00:11:03.061Z] 00:11:03 INFO - PID 26279 | 1556755863057 webdriver::server DEBUG Deleting session
[task 2019-05-02T00:11:03.069Z] 00:11:03 INFO - PID 26279 | 1556755863063 Marionette DEBUG 0 -> [0,3,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2019-05-02T00:11:03.069Z] 00:11:03 INFO - PID 26279 | 1556755863063 Marionette DEBUG 0 <- [1,3,{"error":"invalid session id","message":"Tried to run command without establishing a connection","stacktrace":"WebDriver ... t@chrome://marionette/content/server.js:236:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:492:20\n"},null]
[task 2019-05-02T00:11:03.085Z] 00:11:03 INFO - PID 26279 | 1556755863074 Marionette DEBUG Closed connection 0
[task 2019-05-02T00:11:03.909Z] 00:11:03 INFO - PID 26279 | JavaScript error: resource://activity-stream/lib/PlacesFeed.jsm, line 171: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsINavHistoryService.addObserver]
[task 2019-05-02T00:11:03.909Z] 00:11:03 INFO - PID 26279 | JavaScript error: resource://gre/modules/ExtensionSettingsStore.jsm, line 105: Error: The ExtensionSettingsStore was accessed before the initialize promise resolved.
[task 2019-05-02T00:11:03.910Z] 00:11:03 INFO - PID 26279 |
[task 2019-05-02T00:11:03.910Z] 00:11:03 INFO - PID 26279 | ###!!! [Parent][DispatchAsyncMessage] Error: PBackground::Msg_PBackgroundIDBFactoryConstructor Value error: message was deserialized, but contained an illegal value
[task 2019-05-02T00:11:03.911Z] 00:11:03 INFO - PID 26279 |
[task 2019-05-02T00:11:03.912Z] 00:11:03 INFO - PID 26279 |
[task 2019-05-02T00:11:03.913Z] 00:11:03 INFO - PID 26279 | ###!!! [Parent][DispatchAsyncMessage] Error: PBackgroundIDBFactory::Msg_PBackgroundIDBFactoryRequestConstructor Route error: message sent to unknown actor ID
[task 2019-05-02T00:11:03.914Z] 00:11:03 INFO - PID 26279 |
[task 2019-05-02T00:11:03.915Z] 00:11:03 INFO - PID 26279 | JavaScript error: resource://gre/modules/IndexedDB.jsm, line 349: UnknownError: The operation failed for reasons unrelated to the database itself and not covered by any other error code.
[task 2019-05-02T00:11:03.922Z] 00:11:03 INFO - PID 26279 | JavaScript error: , line 0: AbortError: A request was aborted, for example through a call to IDBTransaction.abort.
[task 2019-05-02T00:11:03.923Z] 00:11:03 INFO - PID 26279 | JavaScript error: , line 0: AbortError: A request was aborted, for example through a call to IDBTransaction.abort.
[task 2019-05-02T00:11:03.923Z] 00:11:03 INFO - PID 26279 | JavaScript error: resource://gre/modules/Sqlite.jsm, line 834: Error: Connection is not open.
[task 2019-05-02T00:11:03.924Z] 00:11:03 INFO - PID 26279 | JavaScript error: , line 0: AbortError: A request was aborted, for example through a call to IDBTransaction.abort.
[task 2019-05-02T00:11:04.214Z] 00:11:04 INFO - PID 26279 | 1556755864207 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2019-05-02T00:11:04.215Z] 00:11:04 INFO - PID 26279 | 1556755864207 Marionette DEBUG Resetting recommended pref apz.content_response_timeout
[task 2019-05-02T00:11:04.216Z] 00:11:04 INFO - PID 26279 | 1556755864207 Marionette DEBUG Resetting recommended pref browser.contentblocking.introCount
[task 2019-05-02T00:11:04.216Z] 00:11:04 INFO - PID 26279 | 1556755864207 Marionette DEBUG Resetting recommended pref browser.download.panel.shown
[task 2019-05-02T00:11:04.217Z] 00:11:04 INFO - PID 26279 | 1556755864207 Marionette DEBUG Resetting recommended pref browser.newtabpage.enabled
[task 2019-05-02T00:11:04.218Z] 00:11:04 INFO - PID 26279 | 1556755864208 Marionette DEBUG Resetting recommended pref browser.pagethumbnails.capturing_disabled
[task 2019-05-02T00:11:04.218Z] 00:11:04 INFO - PID 26279 | 1556755864208 Marionette DEBUG Resetting recommended pref browser.search.update
[task 2019-05-02T00:11:04.222Z] 00:11:04 INFO - PID 26279 | 1556755864208 Marionette DEBUG Resetting recommended pref browser.tabs.disableBackgroundZombification
[task 2019-05-02T00:11:04.223Z] 00:11:04 INFO - PID 26279 | 1556755864208 Marionette DEBUG Resetting recommended pref browser.tabs.warnOnCloseOtherTabs
[task 2019-05-02T00:11:04.224Z] 00:11:04 INFO - PID 26279 | 1556755864208 Marionette DEBUG Resetting recommended pref browser.tabs.warnOnOpen
[task 2019-05-02T00:11:04.224Z] 00:11:04 INFO - PID 26279 | 1556755864209 Marionette DEBUG Resetting recommended pref browser.usedOnWindows10.introURL
[task 2019-05-02T00:11:04.225Z] 00:11:04 INFO - PID 26279 | 1556755864209 Marionette DEBUG Resetting recommended pref browser.urlbar.suggest.searches
[task 2019-05-02T00:11:04.226Z] 00:11:04 INFO - PID 26279 | 1556755864209 Marionette DEBUG Resetting recommended pref datareporting.policy.dataSubmissionPolicyAccepted
[task 2019-05-02T00:11:04.227Z] 00:11:04 INFO - PID 26279 | 1556755864209 Marionette DEBUG Resetting recommended pref dom.disable_beforeunload
[task 2019-05-02T00:11:04.228Z] 00:11:04 INFO - PID 26279 | 1556755864209 Marionette DEBUG Resetting recommended pref dom.disable_open_during_load
[task 2019-05-02T00:11:04.229Z] 00:11:04 INFO - PID 26279 | 1556755864209 Marionette DEBUG Resetting recommended pref dom.file.createInChild
[task 2019-05-02T00:11:04.230Z] 00:11:04 INFO - PID 26279 | 1556755864209 Marionette DEBUG Resetting recommended pref dom.max_chrome_script_run_time
[task 2019-05-02T00:11:04.230Z] 00:11:04 INFO - PID 26279 | 1556755864210 Marionette DEBUG Resetting recommended pref dom.max_script_run_time
[task 2019-05-02T00:11:04.232Z] 00:11:04 INFO - PID 26279 | 1556755864210 Marionette DEBUG Resetting recommended pref extensions.getAddons.cache.enabled
[task 2019-05-02T00:11:04.232Z] 00:11:04 INFO - PID 26279 | 1556755864210 Marionette DEBUG Resetting recommended pref extensions.webservice.discoverURL
[task 2019-05-02T00:11:04.234Z] 00:11:04 INFO - PID 26279 | 1556755864210 Marionette DEBUG Resetting recommended pref network.http.prompt-temp-redirect
[task 2019-05-02T00:11:04.234Z] 00:11:04 INFO - PID 26279 | 1556755864210 Marionette DEBUG Resetting recommended pref network.http.speculative-parallel-limit
[task 2019-05-02T00:11:04.236Z] 00:11:04 INFO - PID 26279 | 1556755864210 Marionette DEBUG Resetting recommended pref security.fileuri.strict_origin_policy
[task 2019-05-02T00:11:04.236Z] 00:11:04 INFO - PID 26279 | 1556755864210 Marionette DEBUG Resetting recommended pref security.notification_enable_delay
[task 2019-05-02T00:11:04.238Z] 00:11:04 INFO - PID 26279 | 1556755864211 Marionette DEBUG Resetting recommended pref signon.autofillForms
[task 2019-05-02T00:11:04.238Z] 00:11:04 INFO - PID 26279 | 1556755864211 Marionette DEBUG Resetting recommended pref signon.rememberSignons
[task 2019-05-02T00:11:04.240Z] 00:11:04 INFO - PID 26279 | 1556755864211 Marionette DEBUG Resetting recommended pref toolkit.cosmeticAnimations.enabled
[task 2019-05-02T00:11:04.240Z] 00:11:04 INFO - PID 26279 | 1556755864212 Marionette DEBUG Remote service is inactive
[task 2019-05-02T00:11:28.273Z] 00:11:28 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/response.py | expected OK
[task 2019-05-02T00:11:28.273Z] 00:11:28 INFO - TEST-INFO took 30003ms
[task 2019-05-02T00:11:28.301Z] 00:11:28 INFO - STDERR: Traceback (most recent call last):
[task 2019-05-02T00:11:28.302Z] 00:11:28 INFO - STDERR: File "/usr/lib/python2.7/multiprocessing/queues.py", line 268, in _feed
[task 2019-05-02T00:11:28.338Z] 00:11:28 INFO - Closing logging queue
[task 2019-05-02T00:11:28.338Z] 00:11:28 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/response.py::test_sessionid
[task 2019-05-02T00:11:28.339Z] 00:11:28 INFO - queue closed
[task 2019-05-02T00:11:28.339Z] 00:11:28 INFO - Starting runner
[task 2019-05-02T00:11:28.355Z] 00:11:28 INFO - WebDriver HTTP server listening at http://127.0.0.1:4444/

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=284060735&repo=mozilla-central&lineNumber=98728

[task 2020-01-08T19:03:43.350Z] 19:03:43 INFO - TEST-START | /webdriver/tests/new_session/response.py
[task 2020-01-08T19:03:43.386Z] 19:03:43 INFO - STDOUT: ============================= test session starts ==============================
[task 2020-01-08T19:03:43.387Z] 19:03:43 INFO - STDOUT: platform linux2 -- Python 2.7.12, pytest-unknown, py-1.5.2, pluggy-0.5.3.dev -- /builds/worker/workspace/build/venv/bin/python
[task 2020-01-08T19:03:43.387Z] 19:03:43 INFO - STDOUT: rootdir: /builds/worker/workspace/build, inifile:
[task 2020-01-08T19:03:43.388Z] 19:03:43 INFO - STDOUT: collecting ...
[task 2020-01-08T19:03:43.415Z] 19:03:43 INFO - STDOUT: collected 18 items
[task 2020-01-08T19:03:43.416Z] 19:03:43 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/response.py::test_sessionid
[task 2020-01-08T19:03:43.421Z] 19:03:43 INFO - PID 3834 | 1578510223411 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"binary": "/builds/worker/workspace/build/application/firefox/firefox", "prefs": {"network.process.enabled": false, "media.peerconnection.mtransport_process": false, "layers.d3d11.enable-blacklist": false, "network.dns.localDomains": "www1.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www1.web-platform.test,www.www2.not-web-platform.test,www2.www2.not-web-platform.test,xn--lve-6lad.www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.not-web-platform.test,not-web-platform.test,www1.www.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.web-platform.test,www2.not-web-platform.test,www1.not-web-platform.test,www1.www1.web-platform.test,www2.xn--lve-6lad.web-platform.test,www1.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www1.www2.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.not-web-platform.test,www2.www1.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.not-web-platform.test,xn--lve-6lad.www.web-platform.test,www.www.web-platform.test,www1.xn--lve-6lad.web-platform.test,xn--lve-6lad.www2.web-platform.test,www.www2.web-platform.test,www2.www.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.not-web-platform.test,www1.www.web-platform.test,www.xn--lve-6lad.web-platform.test,www.www.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.web-platform.test,xn--lve-6lad.www1.not-web-platform.test,www1.www1.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.not-web-platform.test,www2.www2.web-platform.test,xn--lve-6lad.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.web-platform.test,xn--lve-6lad.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,www2.xn--lve-6lad.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.web-platform.test,www1.xn--lve-6lad.not-web-platform.test,www1.web-platform.test,www.www1.web-platform.test,www2.web-platform.test,www.xn--lve-6lad.not-web-platform.test,www.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www1.www2.not-web-platform.test,www2.www1.web-platform.test,www.www1.not-web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test"}}}}}
[task 2020-01-08T19:03:43.422Z] 19:03:43 INFO - PID 3834 | 1578510223413 mozrunner::runner INFO Running command: "/builds/worker/workspace/build/application/firefox/firefox" "-marionette" "-foreground" "-no-remote" "-profile" "/tmp/rust_mozprofileFzIbpB"
[task 2020-01-08T19:03:43.422Z] 19:03:43 INFO - PID 3834 | 1578510223414 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1:2828
[task 2020-01-08T19:03:43.963Z] 19:03:43 INFO - PID 3834 | 1578510223950 addons.webextension.doh-rollout@mozilla.org WARN Loading extension 'doh-rollout@mozilla.org': Reading manifest: Invalid extension permission: networkStatus
[task 2020-01-08T19:03:44.889Z] 19:03:44 INFO - PID 3834 | 1578510224883 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: mozillaAddons
[task 2020-01-08T19:03:44.889Z] 19:03:44 INFO - PID 3834 | 1578510224883 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: telemetry
[task 2020-01-08T19:03:44.890Z] 19:03:44 INFO - PID 3834 | 1578510224883 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: resource://pdf.js/
[task 2020-01-08T19:03:44.891Z] 19:03:44 INFO - PID 3834 | 1578510224883 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: about:reader*
[task 2020-01-08T19:03:45.028Z] 19:03:45 INFO - PID 3834 | 1578510225024 Marionette TRACE Received observer notification profile-after-change
[task 2020-01-08T19:03:45.085Z] 19:03:45 INFO - PID 3834 | 1578510225082 Marionette TRACE Received observer notification command-line-startup
[task 2020-01-08T19:03:45.085Z] 19:03:45 INFO - PID 3834 | 1578510225082 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
[task 2020-01-08T19:03:45.183Z] 19:03:45 INFO - PID 3834 | 1578510225178 Marionette TRACE Received observer notification toplevel-window-ready
[task 2020-01-08T19:03:48.095Z] 19:03:48 INFO - PID 3834 | 1578510228090 Marionette TRACE Received observer notification marionette-startup-requested
[task 2020-01-08T19:03:48.096Z] 19:03:48 INFO - PID 3834 | 1578510228091 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2020-01-08T19:03:48.122Z] 19:03:48 INFO - PID 3834 | 1578510228106 Marionette TRACE All scripts recorded.
[task 2020-01-08T19:03:48.122Z] 19:03:48 INFO - PID 3834 | 1578510228106 Marionette DEBUG Setting recommended pref apz.content_response_timeout to 60000
[task 2020-01-08T19:03:48.122Z] 19:03:48 INFO - PID 3834 | 1578510228107 Marionette DEBUG Setting recommended pref browser.contentblocking.introCount to 99
[task 2020-01-08T19:03:48.122Z] 19:03:48 INFO - PID 3834 | 1578510228107 Marionette DEBUG Setting recommended pref browser.download.panel.shown to true
[task 2020-01-08T19:03:48.122Z] 19:03:48 INFO - PID 3834 | 1578510228107 Marionette DEBUG Setting recommended pref browser.newtabpage.enabled to false
[task 2020-01-08T19:03:48.122Z] 19:03:48 INFO - PID 3834 | 1578510228108 Marionette DEBUG Setting recommended pref browser.pagethumbnails.capturing_disabled to true
[task 2020-01-08T19:03:48.122Z] 19:03:48 INFO - PID 3834 | 1578510228109 Marionette DEBUG Setting recommended pref browser.search.update to false
[task 2020-01-08T19:03:48.122Z] 19:03:48 INFO - PID 3834 | 1578510228109 Marionette DEBUG Setting recommended pref browser.tabs.disableBackgroundZombification to false
[task 2020-01-08T19:03:48.122Z] 19:03:48 INFO - PID 3834 | 1578510228109 Marionette DEBUG Setting recommended pref browser.tabs.remote.separatePrivilegedContentProcess to false
[task 2020-01-08T19:03:48.122Z] 19:03:48 INFO - PID 3834 | 1578510228110 Marionette DEBUG Setting recommended pref browser.tabs.unloadOnLowMemory to false
[task 2020-01-08T19:03:48.122Z] 19:03:48 INFO - PID 3834 | 1578510228110 Marionette DEBUG Setting recommended pref browser.tabs.warnOnCloseOtherTabs to false
[task 2020-01-08T19:03:48.123Z] 19:03:48 INFO - PID 3834 | 1578510228110 Marionette DEBUG Setting recommended pref browser.tabs.warnOnOpen to false
[task 2020-01-08T19:03:48.123Z] 19:03:48 INFO - PID 3834 | 1578510228110 Marionette DEBUG Setting recommended pref browser.usedOnWindows10.introURL to
[task 2020-01-08T19:03:48.132Z] 19:03:48 INFO - PID 3834 | 1578510228110 Marionette DEBUG Setting recommended pref browser.urlbar.suggest.searches to false
[task 2020-01-08T19:03:48.132Z] 19:03:48 INFO - PID 3834 | 1578510228112 Marionette DEBUG Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false

[task 2020-01-08T19:03:48.884Z] 19:03:48 INFO - PID 3834 | JavaScript error: resource://gre/modules/Sqlite.jsm, line 912: Error: Connection is not open.
[task 2020-01-08T19:03:49.001Z] 19:03:49 INFO - PID 3834 |
[task 2020-01-08T19:03:49.001Z] 19:03:49 INFO - PID 3834 | ###!!! [Parent][DispatchAsyncMessage] Error: PBackgroundIDBFactory::Msg_PBackgroundIDBFactoryRequestConstructor Value error: message was deserialized, but contained an illegal value
[task 2020-01-08T19:03:49.001Z] 19:03:49 INFO - PID 3834 |
[task 2020-01-08T19:03:49.001Z] 19:03:49 INFO - PID 3834 | JavaScript error: resource://services-common/kinto-offline-client.js, line 603: Error: IndexedDB list() The operation failed for reasons unrelated to the database itself and not covered by any other error code.
[task 2020-01-08T19:04:03.377Z] 19:04:03 INFO - PID 3834 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 433))
[task 2020-01-08T19:04:13.354Z] 19:04:13 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/response.py | expected OK
[task 2020-01-08T19:04:13.354Z] 19:04:13 INFO - TEST-INFO took 30003ms
[task 2020-01-08T19:04:13.384Z] 19:04:13 INFO - Closing logging queue
[task 2020-01-08T19:04:13.384Z] 19:04:13 INFO - queue closed
[task 2020-01-08T19:04:13.385Z] 19:04:13 INFO - Starting runner
[task 2020-01-08T19:04:13.404Z] 19:04:13 INFO - WebDriver HTTP server listening at http://127.0.0.1:60263/

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
See Also: → 1608086

As it looks like this was an issue with Firefox and didn't happen at all within the last 6 months. As such I assume it got fixed at some point.

Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Flags: needinfo?(hskupin)
Resolution: --- → WORKSFORME
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

This is caused by a shutdown hang of Firefox.

Status: REOPENED → RESOLVED
Closed: 3 years ago2 years ago
Resolution: --- → DUPLICATE
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in before you can comment on or make changes to this bug.