Closed Bug 1509677 Opened 6 years ago Closed 5 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)

Version 3
defect

Tracking

(firefox64 unaffected, firefox65 wontfix, firefox66 fixed)

RESOLVED FIXED
mozilla66
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.

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

Assignee: nobody → hskupin
Status: NEW → RESOLVED
Closed: 5 years ago
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.