Closed Bug 1625413 Opened 5 years ago Closed 5 years ago

Intermittent Fis qr TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/back/back.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

Product:
Remote Protocol
Component:
Marionette
Version:
Version 3
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: cbrindusan, Unassigned)

References

Details

(Keywords: intermittent-failure, regression)

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=294999933&repo=mozilla-central&lineNumber=1614

[task 2020-03-27T05:11:57.483Z] 05:11:57 INFO - TEST-START | /webdriver/tests/back/back.py
[task 2020-03-27T05:11:57.886Z] 05:11:57 INFO - STDOUT: ============================= test session starts ==============================
[task 2020-03-27T05:11:57.889Z] 05:11:57 INFO - STDOUT: platform linux2 -- Python 2.7.17, pytest-unknown, py-1.5.2, pluggy-0.5.3.dev -- /builds/worker/workspace/build/venv/bin/python
[task 2020-03-27T05:11:57.889Z] 05:11:57 INFO - STDOUT: rootdir: /builds/worker/workspace/build, inifile:
[task 2020-03-27T05:11:57.891Z] 05:11:57 INFO - STDOUT: collecting ...
[task 2020-03-27T05:11:57.931Z] 05:11:57 INFO - STDOUT: collected 7 items
[task 2020-03-27T05:11:57.932Z] 05:11:57 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/back/back.py::test_null_response_value
[task 2020-03-27T05:11:57.949Z] 05:11:57 INFO - PID 829 | 1585285917929 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"binary": "/builds/worker/workspace/build/application/firefox/firefox", "prefs": {"dom.serviceWorkers.parent_intercept": true, "media.peerconnection.mtransport_process": false, "layers.d3d11.enable-blacklist": false, "fission.autostart": true, "browser.tabs.documentchannel": true, "network.dns.localDomains": "www1.xn--n8j6ds53lwwkrqhv28a.web-platform.test,op88.web-platform.test,op36.not-web-platform.test,op53.not-web-platform.test,op50.not-web-platform.test,xn--lve-6lad.www.web-platform.test,op98.web-platform.test,op24.not-web-platform.test,op31.not-web-platform.test,op95.not-web-platform.test,op85.web-platform.test,op83.not-web-platform.test,www2.not-web-platform.test,xn--lve-6lad.www.not-web-platform.test,op73.not-web-platform.test,op8.web-platform.test,www2.www2.not-web-platform.test,op89.web-platform.test,op66.web-platform.test,xn--lve-6lad.web-platform.test,op19.not-web-platform.test,www1.www2.web-platform.test,op72.web-platform.test,op24.web-platform.test,op21.not-web-platform.test,xn--lve-6lad.not-web-platform.test,op41.web-platform.test,op79.web-platform.test,op81.not-web-platform.test,op70.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.not-web-platform.test,op78.not-web-platform.test,op6.not-web-platform.test,www1.www.not-web-platform.test,op40.not-web-platform.test,op25.not-web-platform.test,op3.not-web-platform.test,op65.not-web-platform.test,op91.web-platform.test,www.www2.web-platform.test,op80.not-web-platform.test,op59.web-platform.test,op52.not-web-platform.test,xn--lve-6lad.xn--lve-6lad.web-platform.test,op68.not-web-platform.test,op45.not-web-platform.test,op71.not-web-platform.test,op72.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.web-platform.test,op39.web-platform.test,op90.not-web-platform.test,op60.web-platform.test,op58.web-platform.test,op28.web-platform.test,www1.web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--lve-6lad.web-platform.test,op14.web-platform.test,op89.not-web-platform.test,op69.web-platform.test,op49.not-web-platform.test,op40.web-platform.test,op2.not-web-platform.test,op5.not-web-platform.test,www.www2.not-web-platform.test,op77.not-web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.web-platform.test,op7.web-platform.test,op74.web-platform.test,op79.not-web-platform.test,op82.not-web-platform.test,www.www1.web-platform.test,op12.not-web-platform.test,op39.not-web-platform.test,op31.web-platform.test,www.not-web-platform.test,www.www.not-web-platform.test,op44.not-web-platform.test,www1.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.web-platform.test,op58.not-web-platform.test,op14.not-web-platform.test,op30.not-web-platform.test,op62.not-web-platform.test,op61.not-web-platform.test,op92.not-web-platform.test,www2.xn--lve-6lad.web-platform.test,op29.not-web-platform.test,op18.web-platform.test,op73.web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.web-platform.test,op77.web-platform.test,op12.web-platform.test,op54.web-platform.test,op63.web-platform.test,op71.web-platform.test,www2.www1.not-web-platform.test,op95.web-platform.test,op16.web-platform.test,op36.web-platform.test,op27.web-platform.test,www.www.web-platform.test,op98.not-web-platform.test,op64.not-web-platform.test,op29.web-platform.test,op9.web-platform.test,op26.not-web-platform.test,op22.not-web-platform.test,op94.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www2.not-web-platform.test,op44.web-platform.test,op94.not-web-platform.test,op33.web-platform.test,op38.not-web-platform.test,op33.not-web-platform.test,op84.web-platform.test,www1.www1.not-web-platform.test,op23.not-web-platform.test,op57.not-web-platform.test,op54.not-web-platform.test,op85.not-web-platform.test,www2.www2.web-platform.test,op46.not-web-platform.test,op97.not-web-platform.test,op32.web-platform.test,op61.web-platform.test,op70.web-platform.test,www2.web-platform.test,op32.not-web-platform.test,op60.not-web-platform.test,op4.web-platform.test,op43.web-platform.test,op7.not-web-platform.test,op78.web-platform.test,op26.web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.web-platform.test,op96.not-web-platform.test,op51.not-web-platform.test,op41.not-web-platform.test,op76.web-platform.test,op52.web-platform.test,op99.web-platform.test,op35.not-web-platform.test,op99.not-web-platform.test,op86.web-platform.test,not-web-platform.test,op42.not-web-platform.test,op46.web-platform.test,op67.not-web-platform.test,op17.web-platform.test,op90.web-platform.test,op93.web-platform.test,op37.not-web-platform.test,op48.not-web-platform.test,op10.web-platform.test,op55.not-web-platform.test,op4.not-web-platform.test,www1.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,op55.web-platform.test,xn--lve-6lad.www2.web-platform.test,op47.web-platform.test,op51.web-platform.test,op45.web-platform.test,op80.web-platform.test,op68.web-platform.test,op49.web-platform.test,op57.web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.web-platform.test,www.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,op56.not-web-platform.test,web-platform.test,op84.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,xn--lve-6lad.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,op34.not-web-platform.test,op6.web-platform.test,op35.web-platform.test,op67.web-platform.test,op69.not-web-platform.test,op11.not-web-platform.test,op93.not-web-platform.test,www1.www.web-platform.test,op86.not-web-platform.test,op8.not-web-platform.test,www2.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,op92.web-platform.test,xn--lve-6lad.www1.not-web-platform.test,op15.web-platform.test,op13.not-web-platform.test,op13.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.web-platform.test,op75.web-platform.test,op20.not-web-platform.test,op76.not-web-platform.test,op64.web-platform.test,op97.web-platform.test,op37.web-platform.test,op56.web-platform.test,op62.web-platform.test,op82.web-platform.test,op25.web-platform.test,op11.web-platform.test,www.xn--lve-6lad.not-web-platform.test,www2.www1.web-platform.test,op27.not-web-platform.test,op50.web-platform.test,op17.not-web-platform.test,op38.web-platform.test,www2.www.not-web-platform.test,xn--lve-6lad.www1.web-platform.test,op75.not-web-platform.test,op83.web-platform.test,op81.web-platform.test,op15.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.www.not-web-platform.test,op20.web-platform.test,op3.web-platform.test,www1.www2.not-web-platform.test,xn--n8j6ds53lwwkrqhv28a.xn--n8j6ds53lwwkrqhv28a.not-web-platform.test,op2.web-platform.test,op21.web-platform.test,op23.web-platform.test,op42.web-platform.test,op47.not-web-platform.test,www1.www1.web-platform.test,op18.not-web-platform.test,op22.web-platform.test,xn--lve-6lad.xn--lve-6lad.not-web-platform.test,op63.not-web-platform.test,op28.not-web-platform.test,op65.web-platform.test,www.www1.not-web-platform.test,www1.xn--lve-6lad.web-platform.test,op43.not-web-platform.test,op66.not-web-platform.test,www2.www.web-platform.test,op96.web-platform.test,op91.not-web-platform.test,www.xn--lve-6lad.web-platform.test,op1.web-platform.test,op74.not-web-platform.test,op87.web-platform.test,op59.not-web-platform.test,op19.web-platform.test,xn--n8j6ds53lwwkrqhv28a.www1.not-web-platform.test,op9.not-web-platform.test,op88.not-web-platform.test,op53.web-platform.test,www2.xn--lve-6lad.not-web-platform.test,op87.not-web-platform.test,op30.web-platform.test,op10.not-web-platform.test,op48.web-platform.test,op16.not-web-platform.test,op34.web-platform.test,op1.not-web-platform.test,www.web-platform.test,op5.web-platform.test,www1.xn--lve-6lad.not-web-platform.test,xn--lve-6lad.www2.not-web-platform.test", "network.process.enabled": false}}}}}
[task 2020-03-27T05:11:57.950Z] 05:11:57 INFO - PID 829 | 1585285917932 mozrunner::runner INFO Running command: "/builds/worker/workspace/build/application/firefox/firefox" "-marionette" "-foreground" "-no-remote" "-profile" "/tmp/rust_mozprofile3z8Smb"
[task 2020-03-27T05:11:57.950Z] 05:11:57 INFO - PID 829 | 1585285917933 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1:2828
[task 2020-03-27T05:11:58.544Z] 05:11:58 INFO - PID 829 | 1585285918541 addons.webextension.doh-rollout@mozilla.org WARN Loading extension 'doh-rollout@mozilla.org': Reading manifest: Invalid extension permission: networkStatus
[task 2020-03-27T05:11:59.226Z] 05:11:59 INFO - PID 829 | 1585285919219 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: mozillaAddons
[task 2020-03-27T05:11:59.227Z] 05:11:59 INFO - PID 829 | 1585285919219 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: telemetry
[task 2020-03-27T05:11:59.228Z] 05:11:59 INFO - PID 829 | 1585285919219 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: resource://pdf.js/
[task 2020-03-27T05:11:59.229Z] 05:11:59 INFO - PID 829 | 1585285919220 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: about:reader*
[task 2020-03-27T05:12:22.016Z] 05:12:22 INFO - PID 829 | 1585285942012 Marionette TRACE Marionette enabled
[task 2020-03-27T05:12:22.185Z] 05:12:22 INFO - PID 829 | 1585285942180 Marionette TRACE Received observer notification toplevel-window-ready
[task 2020-03-27T05:12:25.464Z] 05:12:25 INFO - PID 829 | 1585285945458 Marionette TRACE Received observer notification marionette-startup-requested
[task 2020-03-27T05:12:25.466Z] 05:12:25 INFO - PID 829 | 1585285945459 Marionette TRACE Waiting until startup recorder finished recording startup scripts...[task 2020-03-27T05:12:25.549Z] 05:12:25 INFO - PID 829 | 1585285945538 Marionette TRACE All scripts recorded.
[task 2020-03-27T05:12:25.550Z] 05:12:25 INFO - PID 829 | 1585285945538 Marionette DEBUG Setting recommended pref apz.content_response_timeout to 60000
[task 2020-03-27T05:12:25.551Z] 05:12:25 INFO - PID 829 | 1585285945539 Marionette DEBUG Setting recommended pref browser.contentblocking.introCount to 99
[task 2020-03-27T05:12:25.551Z] 05:12:25 INFO - PID 829 | 1585285945539 Marionette DEBUG Setting recommended pref browser.download.panel.shown to true
[task 2020-03-27T05:12:25.552Z] 05:12:25 INFO - PID 829 | 1585285945539 Marionette DEBUG Setting recommended pref browser.newtabpage.enabled to false
[task 2020-03-27T05:12:25.561Z] 05:12:25 INFO - PID 829 | 1585285945540 Marionette DEBUG Setting recommended pref browser.pagethumbnails.capturing_disabled to true
[task 2020-03-27T05:12:25.566Z] 05:12:25 INFO - PID 829 | 1585285945541 Marionette DEBUG Setting recommended pref browser.search.update to false
[task 2020-03-27T05:12:25.570Z] 05:12:25 INFO - PID 829 | 1585285945541 Marionette DEBUG Setting recommended pref browser.tabs.disableBackgroundZombification to false
[task 2020-03-27T05:12:25.570Z] 05:12:25 INFO - PID 829 | 1585285945541 Marionette DEBUG Setting recommended pref browser.tabs.remote.separatePrivilegedContentProcess to false
[task 2020-03-27T05:12:25.570Z] 05:12:25 INFO - PID 829 | 1585285945542 Marionette DEBUG Setting recommended pref browser.tabs.unloadOnLowMemory to false
[task 2020-03-27T05:12:25.571Z] 05:12:25 INFO - PID 829 | 1585285945542 Marionette DEBUG Setting recommended pref browser.tabs.warnOnCloseOtherTabs to false
[task 2020-03-27T05:12:25.571Z] 05:12:25 INFO - PID 829 | 1585285945542 Marionette DEBUG Setting recommended pref browser.tabs.warnOnOpen to false
[task 2020-03-27T05:12:25.579Z] 05:12:25 INFO - PID 829 | 1585285945543 Marionette DEBUG Setting recommended pref browser.usedOnWindows10.introURL to
[task 2020-03-27T05:12:25.579Z] 05:12:25 INFO - PID 829 | 1585285945543 Marionette DEBUG Setting recommended pref browser.urlbar.suggest.searches to false
[task 2020-03-27T05:12:25.581Z] 05:12:25 INFO - PID 829 | 1585285945545 Marionette DEBUG Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
[task 2020-03-27T05:12:25.582Z] 05:12:25 INFO - PID 829 | 1585285945545 Marionette DEBUG Setting recommended pref dom.disable_beforeunload to true
[task 2020-03-27T05:12:25.584Z] 05:12:25 INFO - PID 829 | 1585285945545 Marionette DEBUG Setting recommended pref dom.disable_open_during_load to false
[task 2020-03-27T05:12:25.585Z] 05:12:25 INFO - PID 829 | 1585285945546 Marionette DEBUG Setting recommended pref dom.file.createInChild to true
[task 2020-03-27T05:12:25.586Z] 05:12:25 INFO - PID 829 | 1585285945546 Marionette DEBUG Setting recommended pref dom.max_chrome_script_run_time to 0[task 2020-03-27T05:12:25.586Z] 05:12:25 INFO - PID 829 | 1585285945546 Marionette DEBUG Setting recommended pref dom.max_script_run_time to 0
[task 2020-03-27T05:12:25.588Z] 05:12:25 INFO - PID 829 | 1585285945547 Marionette DEBUG Setting recommended pref dom.push.connection.enabled to false
[task 2020-03-27T05:12:25.590Z] 05:12:25 INFO - PID 829 | 1585285945548 Marionette DEBUG Setting recommended pref extensions.getAddons.cache.enabled to false
[task 2020-03-27T05:12:25.591Z] 05:12:25 INFO - PID 829 | 1585285945549 Marionette DEBUG Setting recommended pref extensions.webservice.discoverURL to http://%(server)s/dummy/discoveryURL
[task 2020-03-27T05:12:25.591Z] 05:12:25 INFO - PID 829 | 1585285945549 Marionette DEBUG Setting recommended pref network.http.prompt-temp-redirect to false
[task 2020-03-27T05:12:25.593Z] 05:12:25 INFO - PID 829 | 1585285945549 Marionette DEBUG Setting recommended pref network.http.speculative-parallel-limit to 0
[task 2020-03-27T05:12:25.594Z] 05:12:25 INFO - PID 829 | 1585285945549 Marionette DEBUG Setting recommended pref privacy.trackingprotection.enabled to false
[task 2020-03-27T05:12:25.595Z] 05:12:25 INFO - PID 829 | 1585285945550 Marionette DEBUG Setting recommended pref security.fileuri.strict_origin_policy to false
[task 2020-03-27T05:12:25.597Z] 05:12:25 INFO - PID 829 | 1585285945550 Marionette DEBUG Setting recommended pref security.notification_enable_delay to 0
[task 2020-03-27T05:12:25.598Z] 05:12:25 INFO - PID 829 | 1585285945550 Marionette DEBUG Setting recommended pref signon.autofillForms to false
[task 2020-03-27T05:12:25.599Z] 05:12:25 INFO - PID 829 | 1585285945552 Marionette DEBUG Setting recommended pref signon.rememberSignons to false
[task 2020-03-27T05:12:25.600Z] 05:12:25 INFO - PID 829 | 1585285945553 Marionette DEBUG Setting recommended pref toolkit.cosmeticAnimations.enabled to false
[task 2020-03-27T05:12:25.636Z] 05:12:25 INFO - PID 829 | 1585285945628 Marionette INFO Listening on port 2828
[task 2020-03-27T05:12:25.637Z] 05:12:25 INFO - PID 829 | 1585285945628 Marionette DEBUG Marionette is listening
[task 2020-03-27T05:12:25.713Z] 05:12:25 INFO - PID 829 | 1585285945704 Marionette DEBUG Accepted connection 0 from 127.0.0.1:41676
[task 2020-03-27T05:12:25.714Z] 05:12:25 INFO - PID 829 | 1585285945704 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:2828.
[task 2020-03-27T05:12:25.715Z] 05:12:25 INFO - PID 829 | 1585285945705 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{}]
[task 2020-03-27T05:12:25.752Z] 05:12:25 INFO - PID 829 | 1585285945736 Marionette TRACE [16] Frame script loaded
[task 2020-03-27T05:12:25.754Z] 05:12:25 INFO - PID 829 | 1585285945737 Marionette TRACE [16] Frame script registered
[task 2020-03-27T05:12:25.754Z] 05:12:25 INFO - PID 829 | 1585285945745 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"b2aad03a-55e0-4de7-8c04-633a01ba73b9","capabilities":{"browserName":"firefox","browserVersion":"76.0a ... /rust_mozprofile3z8Smb","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-03-27T05:12:25.755Z] 05:12:25 INFO - PID 829 | 1585285945747 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"b2aad03a-55e0-4de7-8c04-633a01ba73b9","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"76.0a1","moz:accessibilityChecks":false,"moz:buildID":"20200327044807","moz:geckodriverVersion":"0.26.0","moz:headless":false,"moz:processID":842,"moz:profile":"/tmp/rust_mozprofile3z8Smb","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 2020-03-27T05:12:25.757Z] 05:12:25 INFO - PID 829 | 1585285945750 webdriver::server DEBUG -> POST /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window/rect {"width": 800, "height": 600}
[task 2020-03-27T05:12:25.757Z] 05:12:25 INFO - PID 829 | 1585285945751 Marionette DEBUG 0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2020-03-27T05:12:25.798Z] 05:12:25 INFO - PID 829 | 1585285945790 Marionette DEBUG 0 <- [1,2,null,{"x":0,"y":0,"width":800,"height":600}]
[task 2020-03-27T05:12:25.799Z] 05:12:25 INFO - PID 829 | 1585285945792 webdriver::server DEBUG <- 200 OK {"value":{"x":0,"y":0,"width":800,"height":600}}[task 2020-03-27T05:12:25.801Z] 05:12:25 INFO - PID 829 | 1585285945794 webdriver::server DEBUG -> POST /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window/rect {"y": 100, "x": 100}
[task 2020-03-27T05:12:25.801Z] 05:12:25 INFO - PID 829 | 1585285945795 Marionette DEBUG 0 -> [0,3,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2020-03-27T05:12:25.829Z] 05:12:25 INFO - PID 829 | 1585285945823 Marionette DEBUG 0 <- [1,3,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2020-03-27T05:12:25.830Z] 05:12:25 INFO - PID 829 | 1585285945824 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2020-03-27T05:12:25.832Z] 05:12:25 INFO - PID 829 | 1585285945827 webdriver::server DEBUG -> GET /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window
[task 2020-03-27T05:12:25.836Z] 05:12:25 INFO - PID 829 | 1585285945828 Marionette DEBUG 0 -> [0,4,"WebDriver:GetWindowHandle",{}]
[task 2020-03-27T05:12:25.837Z] 05:12:25 INFO - PID 829 | 1585285945828 Marionette DEBUG 0 <- [1,4,null,{"value":"16"}]
[task 2020-03-27T05:12:25.838Z] 05:12:25 INFO - PID 829 | 1585285945829 webdriver::server DEBUG <- 200 OK {"value":"16"}
[task 2020-03-27T05:12:25.843Z] 05:12:25 INFO - PID 829 | 1585285945830 webdriver::server DEBUG -> GET /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window/handles
[task 2020-03-27T05:12:25.843Z] 05:12:25 INFO - PID 829 | 1585285945831 Marionette DEBUG 0 -> [0,5,"WebDriver:GetWindowHandles",{}]
[task 2020-03-27T05:12:25.845Z] 05:12:25 INFO - PID 829 | 1585285945832 Marionette DEBUG 0 <- [1,5,null,["16"]]
[task 2020-03-27T05:12:25.846Z] 05:12:25 INFO - PID 829 | 1585285945833 webdriver::server DEBUG <- 200 OK {"value":["16"]}
[task 2020-03-27T05:12:25.846Z] 05:12:25 INFO - PID 829 | 1585285945835 webdriver::server DEBUG -> POST /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/execute/sync {"args": [], "script": "window.open()"}
[task 2020-03-27T05:12:25.848Z] 05:12:25 INFO - PID 829 | 1585285945836 Marionette DEBUG 0 -> [0,6,"WebDriver:ExecuteScript",{"args":[],"script":"window.open()"}]
[task 2020-03-27T05:12:25.904Z] 05:12:25 INFO - PID 829 | 1585285945901 Marionette TRACE [4294967298] Frame script loaded
[task 2020-03-27T05:12:25.920Z] 05:12:25 INFO - PID 829 | 1585285945910 Marionette TRACE [4294967298] Frame script registered
[task 2020-03-27T05:12:25.937Z] 05:12:25 INFO - PID 829 | 1585285945931 Marionette DEBUG 0 <- [1,6,null,{"value":null}]
[task 2020-03-27T05:12:25.937Z] 05:12:25 INFO - PID 829 | 1585285945933 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-03-27T05:12:25.939Z] 05:12:25 INFO - PID 829 | 1585285945934 webdriver::server DEBUG -> GET /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window/handles
[task 2020-03-27T05:12:25.943Z] 05:12:25 INFO - PID 829 | 1585285945935 Marionette DEBUG 0 -> [0,7,"WebDriver:GetWindowHandles",{}]
[task 2020-03-27T05:12:25.944Z] 05:12:25 INFO - PID 829 | 1585285945936 Marionette DEBUG 0 <- [1,7,null,["16","4294967298"]]
[task 2020-03-27T05:12:25.946Z] 05:12:25 INFO - PID 829 | 1585285945936 webdriver::server DEBUG <- 200 OK {"value":["16","4294967298"]}
[task 2020-03-27T05:12:25.948Z] 05:12:25 INFO - PID 829 | 1585285945938 webdriver::server DEBUG -> GET /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window/handles
[task 2020-03-27T05:12:26.931Z] 05:12:26 INFO - PID 829 | 1585285946920 Marionette DEBUG 0 -> [0,49,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-03-27T05:12:26.935Z] 05:12:26 INFO - PID 829 | 1585285946920 Marionette DEBUG 0 <- [1,49,null,{"value":null}]
[task 2020-03-27T05:12:26.936Z] 05:12:26 INFO - PID 829 | 1585285946921 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-03-27T05:12:26.937Z] 05:12:26 INFO - PID 829 | 1585285946923 webdriver::server DEBUG -> POST /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/timeouts {"pageLoad": 300000}
[task 2020-03-27T05:12:26.937Z] 05:12:26 INFO - PID 829 | 1585285946925 Marionette DEBUG 0 -> [0,50,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-03-27T05:12:26.937Z] 05:12:26 INFO - PID 829 | 1585285946926 Marionette DEBUG 0 <- [1,50,null,{"value":null}]
[task 2020-03-27T05:12:26.939Z] 05:12:26 INFO - PID 829 | 1585285946926 webdriver::server DEBUG <- 200 OK {"value":null}[task 2020-03-27T05:12:26.939Z] 05:12:26 INFO - PID 829 | 1585285946929 webdriver::server DEBUG -> POST /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/timeouts {"script": 30000}
[task 2020-03-27T05:12:26.940Z] 05:12:26 INFO - PID 829 | 1585285946930 Marionette DEBUG 0 -> [0,51,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-03-27T05:12:26.941Z] 05:12:26 INFO - PID 829 | 1585285946931 Marionette DEBUG 0 <- [1,51,null,{"value":null}]
[task 2020-03-27T05:12:26.941Z] 05:12:26 INFO - PID 829 | 1585285946932 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-03-27T05:12:26.942Z] 05:12:26 INFO - PID 829 | 1585285946933 webdriver::server DEBUG -> GET /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window
[task 2020-03-27T05:12:26.943Z] 05:12:26 INFO - PID 829 | 1585285946935 Marionette DEBUG 0 -> [0,52,"WebDriver:GetWindowHandle",{}]
[task 2020-03-27T05:12:26.944Z] 05:12:26 INFO - PID 829 | 1585285946935 Marionette DEBUG 0 <- [1,52,null,{"value":"16"}]
[task 2020-03-27T05:12:26.945Z] 05:12:26 INFO - PID 829 | 1585285946936 webdriver::server DEBUG <- 200 OK {"value":"16"}
[task 2020-03-27T05:12:26.946Z] 05:12:26 INFO - PID 829 | 1585285946939 webdriver::server DEBUG -> GET /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window
[task 2020-03-27T05:12:26.947Z] 05:12:26 INFO - PID 829 | 1585285946940 Marionette DEBUG 0 -> [0,53,"WebDriver:GetWindowHandle",{}]
[task 2020-03-27T05:12:26.948Z] 05:12:26 INFO - PID 829 | 1585285946941 Marionette DEBUG 0 <- [1,53,null,{"value":"16"}]
[task 2020-03-27T05:12:26.949Z] 05:12:26 INFO - PID 829 | 1585285946942 webdriver::server DEBUG <- 200 OK {"value":"16"}
[task 2020-03-27T05:12:26.951Z] 05:12:26 INFO - PID 829 | 1585285946944 webdriver::server DEBUG -> GET /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window/handles
[task 2020-03-27T05:12:26.952Z] 05:12:26 INFO - PID 829 | 1585285946945 Marionette DEBUG 0 -> [0,54,"WebDriver:GetWindowHandles",{}]
[task 2020-03-27T05:12:26.953Z] 05:12:26 INFO - PID 829 | 1585285946946 Marionette DEBUG 0 <- [1,54,null,["16"]]
[task 2020-03-27T05:12:26.955Z] 05:12:26 INFO - PID 829 | 1585285946946 webdriver::server DEBUG <- 200 OK {"value":["16"]}
[task 2020-03-27T05:12:26.956Z] 05:12:26 INFO - PID 829 | 1585285946948 webdriver::server DEBUG -> POST /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window {"handle": "16"}
[task 2020-03-27T05:12:26.957Z] 05:12:26 INFO - PID 829 | 1585285946949 Marionette DEBUG 0 -> [0,55,"WebDriver:SwitchToWindow",{"handle":"16","name":"16"}]
[task 2020-03-27T05:12:26.959Z] 05:12:26 INFO - PID 829 | 1585285946951 Marionette DEBUG 0 <- [1,55,null,{"value":null}]
[task 2020-03-27T05:12:26.960Z] 05:12:26 INFO - PID 829 | 1585285946951 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-03-27T05:12:26.960Z] 05:12:26 INFO - PID 829 | 1585285946953 webdriver::server DEBUG -> POST /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/alert/dismiss {}
[task 2020-03-27T05:12:26.962Z] 05:12:26 INFO - PID 829 | 1585285946954 Marionette DEBUG 0 -> [0,56,"WebDriver:DismissAlert",{}]
[task 2020-03-27T05:12:26.964Z] 05:12:26 INFO - PID 829 | 1585285946954 Marionette DEBUG 0 <- [1,56,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:175:5\nNoSuchAl ... t@chrome://marionette/content/server.js:249:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20\n"},null]
[task 2020-03-27T05:12:26.966Z] 05:12:26 INFO - PID 829 | 1585285946955 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:175:5\nNoSuchAlertError@chrome://marionette/content/error.js:376:5\nGeckoDriver.prototype._checkIfAlertIsPresent@chrome://marionette/content/driver.js:3388:11\nGeckoDriver.prototype.dismissDialog@chrome://marionette/content/driver.js:3301:8\ndespatch@chrome://marionette/content/server.js:305:40\nexecute@chrome://marionette/content/server.js:275:16\nonPacket/<@chrome://marionette/content/server.js:248:20\nonPacket@chrome://marionette/content/server.js:249:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20\n"}}
[task 2020-03-27T05:12:26.967Z] 05:12:26 INFO - PID 829 | 1585285946958 webdriver::server DEBUG -> POST /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window {"handle": "16"}
[task 2020-03-27T05:12:26.968Z] 05:12:26 INFO - PID 829 | 1585285946958 Marionette DEBUG 0 -> [0,57,"WebDriver:SwitchToWindow",{"handle":"16","name":"16"}]
[task 2020-03-27T05:12:26.970Z] 05:12:26 INFO - PID 829 | 1585285946960 Marionette DEBUG 0 <- [1,57,null,{"value":null}][task 2020-03-27T05:12:27.261Z] 05:12:27 INFO - PID 829 | 1585285947247 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-03-27T05:12:27.262Z] 05:12:27 INFO - PID 829 | 1585285947249 webdriver::server DEBUG -> GET /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window/handles
[task 2020-03-27T05:12:27.262Z] 05:12:27 INFO - PID 829 | 1585285947258 Marionette DEBUG 0 -> [0,93,"WebDriver:GetWindowHandles",{}]
[task 2020-03-27T05:12:27.265Z] 05:12:27 INFO - PID 829 | 1585285947258 Marionette DEBUG 0 <- [1,93,null,["16","4294967310"]]
[task 2020-03-27T05:12:27.270Z] 05:12:27 INFO - PID 829 | 1585285947259 webdriver::server DEBUG <- 200 OK {"value":["16","4294967310"]}
[task 2020-03-27T05:12:27.270Z] 05:12:27 INFO - PID 829 | 1585285947261 webdriver::server DEBUG -> GET /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window/handles
[task 2020-03-27T05:12:27.271Z] 05:12:27 INFO - PID 829 | 1585285947262 Marionette DEBUG 0 -> [0,94,"WebDriver:GetWindowHandles",{}]
[task 2020-03-27T05:12:27.271Z] 05:12:27 INFO - PID 829 | 1585285947263 Marionette DEBUG 0 <- [1,94,null,["16","4294967310"]]
[task 2020-03-27T05:12:27.272Z] 05:12:27 INFO - PID 829 | 1585285947263 webdriver::server DEBUG <- 200 OK {"value":["16","4294967310"]}
[task 2020-03-27T05:12:27.272Z] 05:12:27 INFO - PID 829 | 1585285947265 webdriver::server DEBUG -> POST /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/window {"handle": "4294967310"}
[task 2020-03-27T05:12:27.272Z] 05:12:27 INFO - PID 829 | 1585285947266 Marionette DEBUG 0 -> [0,95,"WebDriver:SwitchToWindow",{"handle":"4294967310","name":"4294967310"}]
[task 2020-03-27T05:12:27.275Z] 05:12:27 INFO - PID 829 | 1585285947267 Marionette DEBUG 0 <- [1,95,null,{"value":null}]
[task 2020-03-27T05:12:27.276Z] 05:12:27 INFO - PID 829 | 1585285947268 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-03-27T05:12:27.277Z] 05:12:27 INFO - PID 829 | 1585285947272 webdriver::server DEBUG -> POST /session/b2aad03a-55e0-4de7-8c04-633a01ba73b9/url {"url": "http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&charset=UTF-8&mime=text%2Fhtml"}
[task 2020-03-27T05:12:27.278Z] 05:12:27 INFO - PID 829 | 1585285947273 Marionette DEBUG 0 -> [0,96,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&charset=UTF-8&mime=text%2Fhtml"}]
[task 2020-03-27T05:12:27.286Z] 05:12:27 INFO - PID 829 | 1585285947278 Marionette TRACE [4294967310] Received DOM event beforeunload for about:blank
[task 2020-03-27T05:12:27.302Z] 05:12:27 INFO - PID 829 | 1585285947290 Marionette TRACE [4294967310] Received DOM event pagehide for about:blank
[task 2020-03-27T05:12:27.303Z] 05:12:27 INFO - PID 829 | 1585285947290 Marionette TRACE [4294967310] Received DOM event unload for about:blank
[task 2020-03-27T05:12:27.305Z] 05:12:27 INFO - PID 829 | JavaScript error: chrome://marionette/content/listener.js, line 378: SecurityError: Permission denied to access property "windowUtils" on cross-origin object
[task 2020-03-27T05:12:27.305Z] 05:12:27 INFO - PID 829 | JavaScript error: chrome://marionette/content/listener.js, line 378: SecurityError: Permission denied to access property "windowUtils" on cross-origin object
[task 2020-03-27T05:12:27.502Z] 05:12:27 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/back/back.py | expected OK

This is failing due to:

JavaScript error: chrome://marionette/content/listener.js, line 378: SecurityError: Permission denied to access property "windowUtils" on cross-origin object

So it's blocked on bug 1625410.

Depends on: 1625410
No longer depends on: 1382162, 1540367
Summary: Intermittent Fis TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/back/back.py | expected OK → Perma Fis TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/back/back.py | expected OK
Summary: Perma Fis TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/back/back.py | expected OK → Intermittent Fis TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/back/back.py | expected OK

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #1)

This is failing due to:

JavaScript error: chrome://marionette/content/listener.js, line 378: SecurityError: Permission denied to access property "windowUtils" on cross-origin object

So it's blocked on bug 1625410.

That's actually not true. This doesn't cause the timeout as the current perma passes for this test failure (bug 1628138) indicate. Instead this was caused by a very slow startup of Firefox before the command-line-startup notification, which took 28s:

[task 2020-03-27T05:11:57.950Z] 05:11:57     INFO - PID 829 | 1585285917932	mozrunner::runner	INFO	Running command: "/builds/worker/workspace/build/application/firefox/firefox" "-marionette" "-foreground" "-no-remote" "-profile" "/tmp/rust_mozprofile3z8Smb"
[task 2020-03-27T05:11:57.950Z] 05:11:57     INFO - PID 829 | 1585285917933	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1:2828
[task 2020-03-27T05:11:58.544Z] 05:11:58     INFO - PID 829 | 1585285918541	addons.webextension.doh-rollout@mozilla.org	WARN	Loading extension 'doh-rollout@mozilla.org': Reading manifest: Invalid extension permission: networkStatus
[task 2020-03-27T05:11:59.226Z] 05:11:59     INFO - PID 829 | 1585285919219	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: mozillaAddons
[task 2020-03-27T05:11:59.227Z] 05:11:59     INFO - PID 829 | 1585285919219	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: telemetry
[task 2020-03-27T05:11:59.228Z] 05:11:59     INFO - PID 829 | 1585285919219	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: resource://pdf.js/
[task 2020-03-27T05:11:59.229Z] 05:11:59     INFO - PID 829 | 1585285919220	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: about:reader*
[task 2020-03-27T05:12:22.016Z] 05:12:22     INFO - PID 829 | 1585285942012	Marionette	TRACE	Marionette enabled
[task 2020-03-27T05:12:22.185Z] 05:12:22     INFO - PID 829 | 1585285942180	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-03-27T05:12:25.464Z] 05:12:25     INFO - PID 829 | 1585285945458	Marionette	TRACE	Received observer notification marionette-startup-requested

The failures seem to have been stopped between April 1st and April 6th, and all the recent ones are for bug 1628138. Lets re-check in a week.

Summary: Intermittent Fis TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/back/back.py | expected OK → Intermittent Fis qr TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/back/back.py | expected OK

No more failures since April 7th. Closing as WFM.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → WORKSFORME
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.