Closed Bug 1509677 Opened 6 years ago Closed 6 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py TestSwitchWindowChrome.test_switch_tabs_for_new_background_window_without_focus_change | ScriptTimeoutException: Failed to trigger opening a new tab: Timed

Categories

(Testing :: Marionette Client and Harness, defect, P5)

Product:
Testing
Component:
Marionette Client and Harness
Version:
Version 3
Type:
defect

Tracking

(firefox64 unaffected, firefox65 wontfix, firefox66 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla66
Tracking Flags:
Tracking Status
firefox64 --- unaffected
firefox65 --- wontfix
firefox66 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

Details

(Keywords: intermittent-failure)

Filed by: rmaries [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=213693099&repo=mozilla-central https://queue.taskcluster.net/v1/task/YU7WX9ScS6m_W9uEsWuKDg/runs/0/artifacts/public/logs/live_backing.log 15:08:48 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py TestSwitchWindowChrome.test_switch_tabs_for_new_background_window_without_focus_change 15:08:48 INFO - 1543100928899 Marionette TRACE 39 -> [0,47,"WebDriver:DeleteSession",{}] 15:08:48 INFO - 1543100928901 Marionette TRACE 39 <- [1,47,null,{"value":null}] 15:08:48 INFO - 1543100928902 Marionette DEBUG Closed connection 39 15:08:48 INFO - 1543100928903 Marionette DEBUG Accepted connection 40 from 127.0.0.1:51664 15:08:48 INFO - 1543100928904 Marionette TRACE 40 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}] 15:08:48 INFO - 1543100928905 Marionette DEBUG [2147483649] Frame script loaded 15:08:48 INFO - 1543100928906 Marionette DEBUG [2147483649] Frame script registered 15:08:48 INFO - 1543100928908 Marionette TRACE 40 <- [1,1,null,{"sessionId":"1cc6e87d-29d2-f648-9e2a-4cc36549a51d","capabilities":{"browserName":"firefox","browserVersion":"65.0a ... /T/tmpDWwu4O.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}] 15:08:48 INFO - 1543100928910 Marionette TRACE 40 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}] 15:08:48 INFO - 1543100928910 Marionette TRACE 40 <- [1,2,null,{"value":null}] 15:08:48 INFO - 1543100928911 Marionette TRACE 40 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}] 15:08:48 INFO - 1543100928912 Marionette TRACE 40 <- [1,3,null,{"value":null}] 15:08:48 INFO - 1543100928913 Marionette TRACE 40 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}] 15:08:48 INFO - 1543100928914 Marionette TRACE 40 <- [1,4,null,{"value":null}] 15:08:48 INFO - 1543100928915 Marionette TRACE 40 -> [0,5,"WebDriver:GetChromeWindowHandle",{}] 15:08:48 INFO - 1543100928915 Marionette TRACE 40 <- [1,5,null,{"value":"3"}] 15:08:48 INFO - 1543100928916 Marionette TRACE 40 -> [0,6,"WebDriver:GetChromeWindowHandles",{}] 15:08:48 INFO - 1543100928916 Marionette TRACE 40 <- [1,6,null,["3"]] 15:08:48 INFO - 1543100928917 Marionette TRACE 40 -> [0,7,"WebDriver:GetWindowHandle",{}] 15:08:48 INFO - 1543100928917 Marionette TRACE 40 <- [1,7,null,{"value":"2147483649"}] 15:08:48 INFO - 1543100928918 Marionette TRACE 40 -> [0,8,"WebDriver:GetWindowHandles",{}] 15:08:48 INFO - 1543100928918 Marionette TRACE 40 <- [1,8,null,["2147483649"]] 15:08:48 INFO - 1543100928919 Marionette TRACE 40 -> [0,9,"Marionette:GetContext",{}] 15:08:48 INFO - 1543100928920 Marionette TRACE 40 <- [1,9,null,{"value":"content"}] 15:08:48 INFO - 1543100928921 Marionette TRACE 40 -> [0,10,"Marionette:SetContext",{"value":"chrome"}] 15:08:48 INFO - 1543100928921 Marionette TRACE 40 <- [1,10,null,{"value":null}] 15:08:48 INFO - 1543100928923 Marionette TRACE 40 -> [0,11,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"tests/testing/marionette/harnes ... rowser.selectedTab) {\n return i;\n }\n }","sandbox":"default","line":70}] 15:08:48 INFO - 1543100928925 Marionette TRACE 40 <- [1,11,null,{"value":0}] 15:08:48 INFO - 1543100928926 Marionette TRACE 40 -> [0,12,"Marionette:SetContext",{"value":"content"}] 15:08:48 INFO - 1543100928927 Marionette TRACE 40 <- [1,12,null,{"value":null}] 15:08:48 INFO - 1543100928928 Marionette TRACE 40 -> [0,13,"Marionette:GetContext",{}] 15:08:48 INFO - 1543100928928 Marionette TRACE 40 <- [1,13,null,{"value":"content"}] 15:08:48 INFO - 1543100928929 Marionette TRACE 40 -> [0,14,"Marionette:SetContext",{"value":"content"}] 15:08:48 INFO - 1543100928929 Marionette TRACE 40 <- [1,14,null,{"value":null}] 15:08:48 INFO - 1543100928930 Marionette TRACE 40 -> [0,15,"WebDriver:Navigate",{"url":"http://127.0.0.1:50445/windowHandles.html"}] 15:08:48 INFO - 1543100928933 Marionette DEBUG [2147483649] Received DOM event beforeunload for http://127.0.0.1:50445/windowHandles.html 15:08:48 INFO - 1543100928939 Marionette DEBUG [2147483649] Received DOM event pagehide for http://127.0.0.1:50445/windowHandles.html 15:08:48 INFO - 1543100928940 Marionette DEBUG [2147483649] Received DOM event unload for http://127.0.0.1:50445/windowHandles.html 15:08:48 INFO - 1543100928946 Marionette DEBUG [2147483649] Received DOM event DOMContentLoaded for http://127.0.0.1:50445/windowHandles.html 15:08:48 INFO - 1543100928957 Marionette DEBUG [2147483649] Received DOM event pageshow for http://127.0.0.1:50445/windowHandles.html 15:08:48 INFO - 1543100928958 Marionette TRACE 40 <- [1,15,null,{"value":null}] 15:08:48 INFO - 1543100928970 Marionette TRACE 40 -> [0,16,"Marionette:SetContext",{"value":"content"}] 15:08:48 INFO - 1543100928971 Marionette TRACE 40 <- [1,16,null,{"value":null}] 15:08:48 INFO - 1543100928972 Marionette TRACE 40 -> [0,17,"Marionette:SetContext",{"value":"chrome"}] 15:08:48 INFO - 1543100928973 Marionette TRACE 40 <- [1,17,null,{"value":null}] 15:08:48 INFO - 1543100928974 Marionette TRACE 40 -> [0,18,"WebDriver:GetWindowHandles",{}] 15:08:48 INFO - 1543100928974 Marionette TRACE 40 <- [1,18,null,["2147483649"]] 15:08:48 INFO - 1543100928975 Marionette TRACE 40 -> [0,19,"Marionette:GetContext",{}] 15:08:48 INFO - 1543100928976 Marionette TRACE 40 <- [1,19,null,{"value":"chrome"}] 15:08:48 INFO - 1543100928977 Marionette TRACE 40 -> [0,20,"Marionette:SetContext",{"value":"content"}] 15:08:48 INFO - 1543100928977 Marionette TRACE 40 <- [1,20,null,{"value":null}] 15:08:48 INFO - 1543100928978 Marionette TRACE 40 -> [0,21,"WebDriver:FindElement",{"using":"id","value":"new-tab"}] 15:08:48 INFO - 1543100928983 Marionette TRACE 40 <- [1,21,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"67daedd6-c7da-5544-9c96-6214b1896658"}}] 15:08:48 INFO - 1543100928984 Marionette TRACE 40 -> [0,22,"WebDriver:ElementClick",{"id":"67daedd6-c7da-5544-9c96-6214b1896658"}] 15:08:49 INFO - 1543100928994 Marionette TRACE 40 <- [1,22,null,{"value":null}] 15:08:49 INFO - 1543100929028 Marionette DEBUG [2147483817] Frame script loaded 15:08:49 INFO - 1543100929038 Marionette DEBUG [2147483817] Frame script registered 15:08:49 INFO - 1543100929039 Marionette TRACE 40 -> [0,23,"Marionette:SetContext",{"value":"chrome"}] 15:08:49 INFO - 1543100929040 Marionette TRACE 40 <- [1,23,null,{"value":null}] 15:08:49 INFO - 1543100929061 Marionette TRACE 40 -> [0,24,"WebDriver:GetWindowHandles",{}] 15:08:49 INFO - 1543100929061 Marionette TRACE 40 <- [1,24,null,["2147483649","2147483817"]] 15:08:49 INFO - 1543100929072 Marionette TRACE 40 -> [0,25,"WebDriver:GetWindowHandles",{}] 15:08:49 INFO - 1543100929073 Marionette TRACE 40 <- [1,25,null,["2147483649","2147483817"]] 15:08:49 INFO - 1543100929077 Marionette TRACE 40 -> [0,26,"WebDriver:SwitchToWindow",{"focus":true,"name":"2147483817"}] 15:08:49 INFO - 1543100929079 Marionette TRACE 40 <- [1,26,null,{"value":null}] 15:08:49 INFO - 1543100929106 Marionette TRACE 40 -> [0,27,"Marionette:GetContext",{}] 15:08:49 INFO - 1543100929106 Marionette TRACE 40 <- [1,27,null,{"value":"chrome"}] 15:08:49 INFO - 1543100929108 Marionette TRACE 40 -> [0,28,"Marionette:SetContext",{"value":"chrome"}] 15:08:49 INFO - 1543100929109 Marionette TRACE 40 <- [1,28,null,{"value":null}] 15:08:49 INFO - 1543100929110 Marionette TRACE 40 -> [0,29,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"tests/testing/marionette/harnes ... rowser.selectedTab) {\n return i;\n }\n }","sandbox":"default","line":70}] 15:08:49 INFO - 1543100929113 Marionette TRACE 40 <- [1,29,null,{"value":1}] 15:08:49 INFO - 1543100929118 Marionette TRACE 40 -> [0,30,"Marionette:SetContext",{"value":"chrome"}] 15:08:49 INFO - 1543100929119 Marionette TRACE 40 <- [1,30,null,{"value":null}] 15:08:49 INFO - 1543100929120 Marionette TRACE 40 -> [0,31,"WebDriver:GetWindowHandles",{}] 15:08:49 INFO - 1543100929121 Marionette TRACE 40 <- [1,31,null,["2147483649","2147483817"]] 15:08:49 INFO - 1543100929122 Marionette TRACE 40 -> [0,32,"Marionette:GetContext",{}] 15:08:49 INFO - 1543100929122 Marionette TRACE 40 <- [1,32,null,{"value":"chrome"}] 15:08:49 INFO - 1543100929124 Marionette TRACE 40 -> [0,33,"Marionette:SetContext",{"value":"chrome"}] 15:08:49 INFO - 1543100929124 Marionette TRACE 40 <- [1,33,null,{"value":null}] 15:08:49 INFO - 1543100929126 Marionette TRACE 40 -> [0,34,"WebDriver:ExecuteAsyncScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"tests/testing/marionette/h ... we can't JSON-ify the events it'd get passed.\n callback()\n });","sandbox":"default","line":60}] 15:09:19 INFO - 1543100959131 Marionette TRACE 40 <- [1,34,{"error":"script timeout","message":"Timed out after 30000 ms","stacktrace":"WebDriverError@chrome://marionette/content ... :419:5\ntimeoutHandler@chrome://marionette/content/evaluate.js:100:35\nnotify@resource://gre/modules/Timer.jsm:42:7\n"},null] 15:09:19 INFO - 1543100959133 Marionette TRACE 40 -> [0,35,"Marionette:SetContext",{"value":"chrome"}] 15:09:19 INFO - 1543100959133 Marionette TRACE 40 <- [1,35,null,{"value":null}] 15:09:19 INFO - 1543100959135 Marionette TRACE 40 -> [0,36,"Marionette:GetContext",{}] 15:09:19 INFO - 1543100959136 Marionette TRACE 40 <- [1,36,null,{"value":"chrome"}] 15:09:19 INFO - 1543100959137 Marionette TRACE 40 -> [0,37,"Marionette:SetContext",{"value":"chrome"}] 15:09:19 INFO - 1543100959138 Marionette TRACE 40 <- [1,37,null,{"value":null}] 15:09:19 INFO - 1543100959139 Marionette TRACE 40 -> [0,38,"WebDriver:TakeScreenshot",{"highlights":null,"full":true,"hash":false,"id":null,"scroll":true}] 15:09:19 INFO - 1543100959179 Marionette TRACE 40 <- [1,38,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAPxCAYAAACl+gBxAAAgAElEQVR4nOzdaZSV9Z3o+8qLXuvk9Opz903fk7M6t+/pdV339DrJCTG2 ... AAAIAxAQgAAAAAYwIQAAAAAMYEIAAAAACMCUAAAAAAGBOAAAAAADAmAAEAAABgTAACAAAAwJgABAAAAIAxAQgAAAAAYwFhaUG71isDAAAAAABJRU5ErkJggg=="}] 15:09:19 INFO - 1543100959181 Marionette TRACE 40 -> [0,39,"Marionette:SetContext",{"value":"chrome"}] 15:09:19 INFO - 1543100959182 Marionette TRACE 40 <- [1,39,null,{"value":null}] 15:09:19 INFO - 1543100959184 Marionette TRACE 40 -> [0,40,"Marionette:GetContext",{}] 15:09:19 INFO - 1543100959184 Marionette TRACE 40 <- [1,40,null,{"value":"chrome"}] 15:09:19 INFO - 1543100959185 Marionette TRACE 40 -> [0,41,"Marionette:SetContext",{"value":"content"}] 15:09:19 INFO - 1543100959186 Marionette TRACE 40 <- [1,41,null,{"value":null}] 15:09:19 INFO - 1543100959186 Marionette TRACE 40 -> [0,42,"WebDriver:GetPageSource",{}] 15:09:19 INFO - 1543100959189 Marionette TRACE 40 <- [1,42,null,{"value":"<html><head>\n<title>Marionette Test</title>\n</head>\n<body>\n\n \n</body></html>"}] 15:09:19 INFO - 1543100959190 Marionette TRACE 40 -> [0,43,"Marionette:SetContext",{"value":"chrome"}] 15:09:19 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py TestSwitchWindowChrome.test_switch_tabs_for_new_background_window_without_focus_change | ScriptTimeoutException: Failed to trigger opening a new tab: Timed out after 30000 ms 15:09:19 INFO - stacktrace: 15:09:19 INFO - WebDriverError@chrome://marionette/content/error.js:179:5 15:09:19 INFO - ScriptTimeoutError@chrome://marionette/content/error.js:419:5 15:09:19 INFO - timeoutHandler@chrome://marionette/content/evaluate.js:100:35 15:09:19 INFO - notify@resource://gre/modules/Timer.jsm:42:7 15:09:19 INFO - Traceback (most recent call last): 15:09:19 INFO - File "/Users/cltbld/tasks/task_1543072631/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run 15:09:19 INFO - testMethod() 15:09:19 INFO - File "/Users/cltbld/tasks/task_1543072631/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py", line 77, in test_switch_tabs_for_new_background_window_without_focus_change 15:09:19 INFO - tab_in_new_window = self.open_tab(trigger=self.open_window_in_background) 15:09:19 INFO - File "/Users/cltbld/tasks/task_1543072631/build/venv/lib/python2.7/site-packages/marionette_harness/runner/mixins/window_manager.py", line 74, in open_tab 15:09:19 INFO - reraise(exc, 'Failed to trigger opening a new tab: {}'.format(val), tb) 15:09:19 INFO - File "/Users/cltbld/tasks/task_1543072631/build/venv/lib/python2.7/site-packages/marionette_harness/runner/mixins/window_manager.py", line 68, in open_tab 15:09:19 INFO - trigger() 15:09:19 INFO - File "/Users/cltbld/tasks/task_1543072631/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py", line 60, in open_window_in_background 15:09:19 INFO - """) 15:09:19 INFO - File "/Users/cltbld/tasks/task_1543072631/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1789, in execute_async_script 15:09:19 INFO - rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value") 15:09:19 INFO - File "/Users/cltbld/tasks/task_1543072631/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _ 15:09:19 INFO - return func(*args, **kwargs) 15:09:19 INFO - File "/Users/cltbld/tasks/task_1543072631/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 764, in _send_message 15:09:19 INFO - self._handle_error(err) 15:09:19 INFO - File "/Users/cltbld/tasks/task_1543072631/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 784, in _handle_error 15:09:19 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace) 15:09:19 INFO - TEST-INFO took 30289ms 15:09:19 INFO - 1543100959190 Marionette TRACE 40 <- [1,43,null,{"value":null}] 15:09:19 INFO - 1543100959193 Marionette TRACE 40 -> [0,44,"WebDriver:GetChromeWindowHandles",{}] 15:09:19 INFO - 1543100959194 Marionette TRACE 40 <- [1,44,null,["3","173"]] 15:09:19 INFO - 1543100959196 Marionette TRACE 40 -> [0,45,"WebDriver:SwitchToWindow",{"focus":true,"name":"173"}] 15:09:19 INFO - 1543100959224 Marionette DEBUG [8589934593] Frame script loaded 15:09:19 INFO - 1543100959226 Marionette DEBUG [8589934593] Frame script registered 15:09:19 INFO - 1543100959226 Marionette TRACE 40 <- [1,45,null,{"value":null}] 15:09:19 INFO - 1543100959227 Marionette TRACE 40 -> [0,46,"WebDriver:CloseChromeWindow",{}] 15:09:19 INFO - 1543100959249 Marionette DEBUG Received observer notification message-manager-disconnect 15:09:19 INFO - 1543100959250 Marionette TRACE 40 <- [1,46,null,["3"]] 15:09:19 INFO - 1543100959265 Marionette TRACE 40 -> [0,47,"WebDriver:SwitchToWindow",{"focus":true,"name":"3"}] 15:09:19 INFO - 1543100959265 Marionette TRACE 40 <- [1,47,null,{"value":null}] 15:09:19 INFO - 1543100959266 Marionette TRACE 40 -> [0,48,"WebDriver:GetWindowHandles",{}] 15:09:19 INFO - 1543100959267 Marionette TRACE 40 <- [1,48,null,["2147483649","2147483817"]] 15:09:19 INFO - 1543100959268 Marionette TRACE 40 -> [0,49,"WebDriver:SwitchToWindow",{"focus":true,"name":"2147483817"}] 15:09:19 INFO - 1543100959268 Marionette TRACE 40 <- [1,49,null,{"value":null}] 15:09:19 INFO - 1543100959269 Marionette TRACE 40 -> [0,50,"WebDriver:CloseWindow",{}] 15:09:19 INFO - 1543100959304 Marionette DEBUG Received observer notification message-manager-disconnect 15:09:19 INFO - 1543100959304 Marionette TRACE 40 <- [1,50,null,["2147483649"]] 15:09:19 INFO - 1543100959306 Marionette TRACE 40 -> [0,51,"WebDriver:SwitchToWindow",{"focus":true,"name":"2147483649"}] 15:09:19 INFO - 1543100959307 Marionette TRACE 40 <- [1,51,null,{"value":null}] 15:09:19 INFO - 1543100959309 Marionette TRACE 40 -> [0,52,"WebDriver:GetChromeWindowHandles",{}] 15:09:19 INFO - 1543100959310 Marionette TRACE 40 <- [1,52,null,["3"]] 15:09:19 INFO - 1543100959310 Marionette TRACE 40 -> [0,53,"WebDriver:GetWindowHandles",{}] 15:09:19 INFO - 1543100959311 Marionette TRACE 40 <- [1,53,null,["2147483649"]] 15:09:19 INFO - 1543100959312 Marionette TRACE 40 -> [0,54,"WebDriver:DeleteSession",{}] 15:09:19 INFO - 1543100959313 Marionette TRACE 40 <- [1,54,null,{"value":null}]
This is a new failure and most likely related to the changes from bug 1506796. I assume that there is an issue with the focus/activate events not being sent, and as such the script timing out: https://searchfox.org/mozilla-central/rev/d35199ef15ffa57d190886e20d5df6471faf0870/testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py#31-60 Also see a discussion on bug 1509380 about the same topic. The underlying issue here should go away once my patch for bug 1504756 has been landed.
status-firefox64: --- → unaffected
status-firefox65: --- → affected
Depends on: 1504756, 1506796

With the patch on bug 1504756 landed, this should no longer be a problem.

Assignee: nobody → hskupin
Status: NEW → RESOLVED
Closed: 6 years ago
status-firefox66: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla66
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.