Closed Bug 1559992 Opened 5 years ago Closed 3 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py TestTabModalAlerts.test_handle_two_dialogs | NoAlertPresentException:

Categories

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

Version 3
Desktop
Linux
defect

Tracking

(firefox-esr78 fixed, firefox86 wontfix, firefox87 fixed)

RESOLVED FIXED
87 Branch
Tracking Status
firefox-esr78 --- fixed
firefox86 --- wontfix
firefox87 --- fixed

People

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

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell unknown])

Attachments

(1 file)

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


[task 2019-06-18T17:09:14.524Z] 17:09:14 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py TestTabModalAlerts.test_handle_two_dialogs
[task 2019-06-18T17:09:14.524Z] 17:09:14 INFO - 1560877754517 Marionette DEBUG 20 <- [1,32,null,{"value":null}]
[task 2019-06-18T17:09:14.524Z] 17:09:14 INFO - 1560877754520 Marionette DEBUG Closed connection 20
[task 2019-06-18T17:09:14.532Z] 17:09:14 INFO - 1560877754527 Marionette DEBUG Accepted connection 21 from 127.0.0.1:55386
[task 2019-06-18T17:09:14.532Z] 17:09:14 INFO - 1560877754530 Marionette DEBUG 21 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-06-18T17:09:14.549Z] 17:09:14 INFO - 1560877754543 Marionette TRACE [2147483649] Frame script loaded
[task 2019-06-18T17:09:14.549Z] 17:09:14 INFO - 1560877754546 Marionette TRACE [2147483649] Frame script registered
[task 2019-06-18T17:09:14.565Z] 17:09:14 INFO - 1560877754560 Marionette DEBUG 21 <- [1,1,null,{"sessionId":"c42f2265-fde0-4495-85b1-60d7924bf514","capabilities":{"browserName":"firefox","browserVersion":"69.0a ... p/tmpYQC9xl.mozrunner","moz:shutdownTimeout":180000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-06-18T17:09:14.566Z] 17:09:14 INFO - 1560877754564 Marionette DEBUG 21 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2019-06-18T17:09:14.575Z] 17:09:14 INFO - 1560877754569 Marionette DEBUG 21 <- [1,2,null,{"value":null}]
[task 2019-06-18T17:09:14.577Z] 17:09:14 INFO - 1560877754574 Marionette DEBUG 21 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2019-06-18T17:09:14.584Z] 17:09:14 INFO - 1560877754578 Marionette DEBUG 21 <- [1,3,null,{"value":null}]
[task 2019-06-18T17:09:14.600Z] 17:09:14 INFO - 1560877754593 Marionette DEBUG 21 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2019-06-18T17:09:14.601Z] 17:09:14 INFO - 1560877754597 Marionette DEBUG 21 <- [1,4,null,{"value":null}]
[task 2019-06-18T17:09:14.602Z] 17:09:14 INFO - 1560877754599 Marionette DEBUG 21 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2019-06-18T17:09:14.610Z] 17:09:14 INFO - 1560877754605 Marionette DEBUG 21 <- [1,5,null,{"value":"1"}]
[task 2019-06-18T17:09:14.618Z] 17:09:14 INFO - 1560877754611 Marionette DEBUG 21 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2019-06-18T17:09:14.626Z] 17:09:14 INFO - 1560877754619 Marionette DEBUG 21 <- [1,6,null,["1"]]
[task 2019-06-18T17:09:14.626Z] 17:09:14 INFO - 1560877754621 Marionette DEBUG 21 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2019-06-18T17:09:14.626Z] 17:09:14 INFO - 1560877754622 Marionette DEBUG 21 <- [1,7,null,{"value":"2147483649"}]
[task 2019-06-18T17:09:14.629Z] 17:09:14 INFO - 1560877754626 Marionette DEBUG 21 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2019-06-18T17:09:14.630Z] 17:09:14 INFO - 1560877754628 Marionette DEBUG 21 <- [1,8,null,["2147483649"]]
[task 2019-06-18T17:09:14.633Z] 17:09:14 INFO - 1560877754631 Marionette DEBUG 21 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2019-06-18T17:09:14.635Z] 17:09:14 INFO - 1560877754633 Marionette DEBUG 21 <- [1,9,null,["2147483649"]]
[task 2019-06-18T17:09:14.638Z] 17:09:14 INFO - 1560877754636 Marionette DEBUG 21 -> [0,10,"WebDriver:NewWindow",{"type":"tab","focus":false}]
[task 2019-06-18T17:09:14.695Z] 17:09:14 INFO - 1560877754682 Marionette TRACE Received DOM event TabOpen for [object XULElement]
[task 2019-06-18T17:09:15.304Z] 17:09:15 INFO - 1560877755291 Marionette TRACE [25769803777] Frame script loaded
[task 2019-06-18T17:09:15.304Z] 17:09:15 INFO - 1560877755294 Marionette TRACE [25769803777] Frame script registered
[task 2019-06-18T17:09:15.340Z] 17:09:15 INFO - 1560877755330 Marionette DEBUG 21 <- [1,10,null,{"handle":"25769803777","type":"tab"}]
[task 2019-06-18T17:09:15.341Z] 17:09:15 INFO - 1560877755334 Marionette DEBUG 21 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2019-06-18T17:09:15.342Z] 17:09:15 INFO - 1560877755336 Marionette DEBUG 21 <- [1,11,null,["2147483649","25769803777"]]
[task 2019-06-18T17:09:15.406Z] 17:09:15 INFO - 1560877755401 Marionette DEBUG 21 -> [0,12,"WebDriver:GetWindowHandles",{}]
[task 2019-06-18T17:09:15.407Z] 17:09:15 INFO - 1560877755402 Marionette DEBUG 21 <- [1,12,null,["2147483649","25769803777"]]
[task 2019-06-18T17:09:15.407Z] 17:09:15 INFO - 1560877755405 Marionette DEBUG 21 -> [0,13,"WebDriver:SwitchToWindow",{"handle":"25769803777","focus":true,"name":"25769803777"}]
[task 2019-06-18T17:09:15.463Z] 17:09:15 INFO - 1560877755461 Marionette TRACE Received DOM event TabSelect for [object XULElement]
[task 2019-06-18T17:09:15.572Z] 17:09:15 INFO - 1560877755569 Marionette DEBUG 21 <- [1,13,null,{"value":null}]
[task 2019-06-18T17:09:15.588Z] 17:09:15 INFO - 1560877755583 Marionette DEBUG 21 -> [0,14,"Marionette:GetContext",{}]
[task 2019-06-18T17:09:15.589Z] 17:09:15 INFO - 1560877755584 Marionette DEBUG 21 <- [1,14,null,{"value":"content"}]
[task 2019-06-18T17:09:15.590Z] 17:09:15 INFO - 1560877755587 Marionette DEBUG 21 -> [0,15,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-06-18T17:09:15.598Z] 17:09:15 INFO - 1560877755591 Marionette DEBUG 21 <- [1,15,null,{"value":null}]
[task 2019-06-18T17:09:15.635Z] 17:09:15 INFO - 1560877755621 Marionette DEBUG 21 -> [0,16,"WebDriver:ExecuteScript",{"script":"Components.utils.import("resource://gre/modules/Preferences.jsm");\n\n ... cified"],"filename":"../../venv/lib/python2.7/site-packages/marionette_driver/marionette.py","sandbox":"default","line":732}]
[task 2019-06-18T17:09:15.635Z] 17:09:15 INFO - 1560877755631 Marionette DEBUG 21 <- [1,16,null,{"value":true}]
[task 2019-06-18T17:09:15.651Z] 17:09:15 INFO - 1560877755639 Marionette DEBUG 21 -> [0,17,"Marionette:SetContext",{"value":"content"}]
[task 2019-06-18T17:09:15.652Z] 17:09:15 INFO - 1560877755640 Marionette DEBUG 21 <- [1,17,null,{"value":null}]
[task 2019-06-18T17:09:15.652Z] 17:09:15 INFO - 1560877755642 Marionette DEBUG 21 -> [0,18,"WebDriver:Navigate",{"url":"http://127.0.0.1:45659/test_tab_modal_dialogs.html"}]
[task 2019-06-18T17:09:15.682Z] 17:09:15 INFO - 1560877755673 Marionette TRACE [25769803777] Received DOM event beforeunload for about:blank
[task 2019-06-18T17:09:15.732Z] 17:09:15 INFO - 1560877755723 Marionette TRACE [25769803777] Received DOM event pagehide for about:blank
[task 2019-06-18T17:09:15.874Z] 17:09:15 INFO - 1560877755866 Marionette TRACE [25769803777] Received DOM event DOMContentLoaded for http://127.0.0.1:45659/test_tab_modal_dialogs.html
[task 2019-06-18T17:09:15.915Z] 17:09:15 INFO - 1560877755911 Marionette TRACE [25769803777] Received DOM event pageshow for http://127.0.0.1:45659/test_tab_modal_dialogs.html
[task 2019-06-18T17:09:15.943Z] 17:09:15 INFO - 1560877755938 Marionette DEBUG 21 <- [1,18,null,{"value":null}]
[task 2019-06-18T17:09:15.992Z] 17:09:15 INFO - 1560877755988 Marionette DEBUG 21 -> [0,19,"WebDriver:FindElement",{"using":"id","value":"open-two-dialogs"}]
[task 2019-06-18T17:09:16.012Z] 17:09:16 INFO - 1560877756009 Marionette DEBUG 21 <- [1,19,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"256ab36a-ac80-4ccb-8b64-55d30945b6d4"}}]
[task 2019-06-18T17:09:16.016Z] 17:09:16 INFO - 1560877756012 Marionette DEBUG 21 -> [0,20,"WebDriver:ElementClick",{"id":"256ab36a-ac80-4ccb-8b64-55d30945b6d4"}]
[task 2019-06-18T17:09:16.154Z] 17:09:16 INFO - 1560877756146 Marionette TRACE Received observer notification tabmodal-dialog-loaded
[task 2019-06-18T17:09:16.162Z] 17:09:16 INFO - 1560877756159 Marionette DEBUG 21 <- [1,20,null,{"value":null}]
[task 2019-06-18T17:09:16.190Z] 17:09:16 INFO - 1560877756186 Marionette DEBUG 21 -> [0,21,"WebDriver:SendAlertText",{"text":"foo"}]
[task 2019-06-18T17:09:16.192Z] 17:09:16 INFO - 1560877756189 Marionette DEBUG 21 <- [1,21,null,{"value":null}]
[task 2019-06-18T17:09:16.208Z] 17:09:16 INFO - 1560877756201 Marionette DEBUG 21 -> [0,22,"WebDriver:AcceptAlert",{}]
[task 2019-06-18T17:09:16.210Z] 17:09:16 INFO - 1560877756207 Marionette TRACE Received event DOMModalDialogClosed
[task 2019-06-18T17:09:16.211Z] 17:09:16 INFO - 1560877756208 Marionette TRACE Received DOM event DOMModalDialogClosed for [object XULFrameElement]
[task 2019-06-18T17:09:16.232Z] 17:09:16 INFO - 1560877756227 Marionette DEBUG 21 <- [1,22,null,{"value":null}]
[task 2019-06-18T17:09:16.248Z] 17:09:16 INFO - 1560877756237 Marionette DEBUG 21 -> [0,23,"WebDriver:SendAlertText",{"text":"bar"}]
[task 2019-06-18T17:09:16.248Z] 17:09:16 INFO - 1560877756239 Marionette DEBUG 21 <- [1,23,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:179:5\nNoSuchAl ... t@chrome://marionette/content/server.js:236:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:492:20\n"},null]
[task 2019-06-18T17:09:16.276Z] 17:09:16 INFO - 1560877756271 Marionette TRACE Received observer notification tabmodal-dialog-loaded
[task 2019-06-18T17:09:16.298Z] 17:09:16 INFO - 1560877756295 Marionette DEBUG 21 -> [0,24,"Marionette:GetContext",{}]
[task 2019-06-18T17:09:16.299Z] 17:09:16 INFO - 1560877756296 Marionette DEBUG 21 <- [1,24,null,{"value":"content"}]
[task 2019-06-18T17:09:16.307Z] 17:09:16 INFO - 1560877756301 Marionette DEBUG 21 -> [0,25,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-06-18T17:09:16.308Z] 17:09:16 INFO - 1560877756303 Marionette DEBUG 21 <- [1,25,null,{"value":null}]
[task 2019-06-18T17:09:16.309Z] 17:09:16 INFO - 1560877756306 Marionette DEBUG 21 -> [0,26,"WebDriver:TakeScreenshot",{"highlights":null,"full":true,"hash":false,"id":null,"scroll":true}]
[task 2019-06-18T17:09:16.429Z] 17:09:16 INFO - 1560877756420 Marionette DEBUG 21 <- [1,26,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4nOzdWYyd933YfV4WzX2ucxMDKhogQQu/AUwgLVr0wiDQxgXi ... fx1Ft6957TrQmAAAAAIACywrn/8n2rgPTc480095c2n1sTAAEAAEAABMIEQAAAABAAgTABEAAAAARAIEwABAAAgJ9O/wUrDZLFKairaAAAAABJRU5ErkJggg=="}]
[task 2019-06-18T17:09:16.446Z] 17:09:16 INFO - 1560877756434 Marionette DEBUG 21 -> [0,27,"Marionette:SetContext",{"value":"content"}]
[task 2019-06-18T17:09:16.448Z] 17:09:16 INFO - 1560877756435 Marionette DEBUG 21 <- [1,27,null,{"value":null}]
[task 2019-06-18T17:09:16.450Z] 17:09:16 INFO - 1560877756437 Marionette DEBUG 21 -> [0,28,"Marionette:GetContext",{}]
[task 2019-06-18T17:09:16.451Z] 17:09:16 INFO - 1560877756437 Marionette DEBUG 21 <- [1,28,null,{"value":"content"}]
[task 2019-06-18T17:09:16.453Z] 17:09:16 INFO - 1560877756439 Marionette DEBUG 21 -> [0,29,"Marionette:SetContext",{"value":"content"}]
[task 2019-06-18T17:09:16.458Z] 17:09:16 INFO - 1560877756440 Marionette DEBUG 21 <- [1,29,null,{"value":null}]
[task 2019-06-18T17:09:16.459Z] 17:09:16 INFO - 1560877756442 Marionette DEBUG 21 -> [0,30,"WebDriver:GetPageSource",{}]
[task 2019-06-18T17:09:16.461Z] 17:09:16 INFO - 1560877756452 Marionette TRACE Received event DOMModalDialogClosed
[task 2019-06-18T17:09:16.461Z] 17:09:16 INFO - 1560877756454 Marionette TRACE Received DOM event DOMModalDialogClosed for [object XULFrameElement]
[task 2019-06-18T17:09:16.479Z] 17:09:16 INFO - 1560877756463 Marionette DEBUG 21 <- [1,30,{"error":"unexpected alert open","message":"Dismissed user prompt dialog: Second","stacktrace":"WebDriverError@chrome:/ ... t@chrome://marionette/content/server.js:236:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:492:20\n"},null]
[task 2019-06-18T17:09:16.481Z] 17:09:16 INFO - 1560877756470 Marionette DEBUG 21 -> [0,31,"Marionette:SetContext",{"value":"content"}]
[task 2019-06-18T17:09:16.485Z] 17:09:16 WARNING - Failed to gather test failure debug: Dismissed user prompt dialog: Second
[task 2019-06-18T17:09:16.486Z] 17:09:16 WARNING - stacktrace:
[task 2019-06-18T17:09:16.487Z] 17:09:16 WARNING - WebDriverError@chrome://marionette/content/error.js:179:5
[task 2019-06-18T17:09:16.488Z] 17:09:16 WARNING - UnexpectedAlertOpenError@chrome://marionette/content/error.js:462:5
[task 2019-06-18T17:09:16.489Z] 17:09:16 WARNING - GeckoDriver.prototype._handleUserPrompts@chrome://marionette/content/driver.js:3290:13
[task 2019-06-18T17:09:16.491Z] 17:09:16 WARNING - async*GeckoDriver.prototype.getPageSource@chrome://marionette/content/driver.js:1165:14
[task 2019-06-18T17:09:16.491Z] 17:09:16 WARNING - despatch@chrome://marionette/content/server.js:289:40
[task 2019-06-18T17:09:16.493Z] 17:09:16 WARNING - execute@chrome://marionette/content/server.js:262:16
[task 2019-06-18T17:09:16.493Z] 17:09:16 WARNING - onPacket/<@chrome://marionette/content/server.js:235:20
[task 2019-06-18T17:09:16.494Z] 17:09:16 WARNING - onPacket@chrome://marionette/content/server.js:236:9
[task 2019-06-18T17:09:16.495Z] 17:09:16 WARNING - _onJSONObjectReady/<@chrome://marionette/content/transport.js:492:20
[task 2019-06-18T17:09:16.496Z] 17:09:16 WARNING -
[task 2019-06-18T17:09:16.496Z] 17:09:16 INFO - 1560877756471 Marionette DEBUG 21 <- [1,31,null,{"value":null}]
[task 2019-06-18T17:09:16.524Z] 17:09:16 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py TestTabModalAlerts.test_handle_two_dialogs | NoAlertPresentException:

Depends on: 1560015

Maybe bug 1631362 contributed on-top of the already known intermittent failures. Lets re-check by next week.

So the click on a link will open two tabmodal prompts right after each other.

INFO -  1590192678042  Marionette  DEBUG   22 -> [0,20,"WebDriver:ElementClick",{"id":"8b20809c-a7ce-4938-9e79-6438492d067e"}]
INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
INFO -  [Parent 9710, Main Thread] WARNING: '!mLastFocusedWindow', file /builds/worker/checkouts/gecko/widget/gtk/IMContextWrapper.cpp, line 3098
INFO -  1590192678154  Marionette  TRACE   Received observer notification tabmodal-dialog-loaded
INFO -  1590192678163  Marionette  DEBUG   22 <- [1,20,null,{"value":null}]
INFO -  1590192678175  Marionette  DEBUG   22 -> [0,21,"WebDriver:SendAlertText",{"text":"foo"}]
INFO -  1590192678178  Marionette  DEBUG   22 <- [1,21,null,{"value":null}]
INFO -  1590192678191  Marionette  DEBUG   22 -> [0,22,"WebDriver:AcceptAlert",{}]
INFO -  [Parent 9710, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp, line 1579
INFO -  1590192678198  Marionette  TRACE   Received event DOMModalDialogClosed
INFO -  1590192678200  Marionette  TRACE   Received DOM event DOMModalDialogClosed for [object XULFrameElement]
INFO -  1590192678213  Marionette  DEBUG   22 <- [1,22,null,{"value":null}]
INFO -  1590192678221  Marionette  DEBUG   22 -> [0,23,"WebDriver:SendAlertText",{"text":"bar"}]
INFO -  1590192678223  Marionette  DEBUG   22 <- [1,23,{"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]
INFO -  [Parent 9710, Main Thread] WARNING: '!mLastFocusedWindow', file /builds/worker/checkouts/gecko/widget/gtk/IMContextWrapper.cpp, line 3098
INFO -  1590192678244  Marionette  TRACE   Received observer notification tabmodal-dialog-loaded

In working cases it looks like:

[task 2020-05-24T22:07:32.158Z] 22:07:32     INFO -  1590358052101	Marionette	DEBUG	22 -> [0,21,"WebDriver:SendAlertText",{"text":"foo"}]
[task 2020-05-24T22:07:32.158Z] 22:07:32     INFO -  1590358052103	Marionette	DEBUG	22 <- [1,21,null,{"value":null}]
[task 2020-05-24T22:07:32.159Z] 22:07:32     INFO -  1590358052121	Marionette	DEBUG	22 -> [0,22,"WebDriver:AcceptAlert",{}]
[task 2020-05-24T22:07:32.162Z] 22:07:32     INFO -  [Parent 1973, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp, line 1579
[task 2020-05-24T22:07:32.172Z] 22:07:32     INFO -  1590358052164	Marionette	TRACE	Received event DOMModalDialogClosed
[task 2020-05-24T22:07:32.209Z] 22:07:32     INFO -  1590358052193	Marionette	TRACE	Received DOM event DOMModalDialogClosed for [object XULFrameElement]
[task 2020-05-24T22:07:32.267Z] 22:07:32     INFO -  1590358052244	Marionette	TRACE	Received observer notification tabmodal-dialog-loaded
[task 2020-05-24T22:07:32.313Z] 22:07:32     INFO -  1590358052294	Marionette	DEBUG	22 <- [1,22,null,{"value":null}]
[task 2020-05-24T22:07:32.313Z] 22:07:32     INFO -  1590358052311	Marionette	DEBUG	22 -> [0,23,"WebDriver:SendAlertText",{"text":"bar"}]
[task 2020-05-24T22:07:32.390Z] 22:07:32     INFO -  1590358052314	Marionette	DEBUG	22 <- [1,23,null,{"value":null}]

Olli, what is the actual expected behavior here? Should the Javascript code as executed by the click event block further processing on the main thread, and as such any other JS code? If not we would have to wait for the next alert to be opened. Right now it's a kinda racy behavior for this specific test. Thanks

Flags: needinfo?(bugs)

Oh, sorry. I missed that bug 1560015 blocks us here, and we got an answer over there already.

Flags: needinfo?(bugs)

All the recent failures are basically happening on ubuntu18.04.

Blocks: 1600387

In the past week there were 23 failures on
-linux1804-64 opt
-linux1804-64 debug
-linux1804-64-asan opt.

Recent failure log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=306037190&repo=autoland&lineNumber=25887

[task 2020-06-12T01:03:12.168Z] 01:03:12 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_window_close_content.py TestCloseWindow.test_close_browserless_tab
[task 2020-06-12T01:03:12.168Z] 01:03:12 INFO - 1591923792156 Marionette DEBUG Closed connection 68
[task 2020-06-12T01:03:12.168Z] 01:03:12 INFO - 1591923792163 Marionette DEBUG Accepted connection 69 from 127.0.0.1:54810
[task 2020-06-12T01:03:12.172Z] 01:03:12 INFO - 1591923792169 Marionette DEBUG 69 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-06-12T01:03:12.175Z] 01:03:12 INFO - 1591923792172 Marionette TRACE [95] Frame script loaded
[task 2020-06-12T01:03:12.175Z] 01:03:12 INFO - 1591923792173 Marionette TRACE [95] Frame script registered
[task 2020-06-12T01:03:12.179Z] 01:03:12 INFO - 1591923792176 Marionette DEBUG 69 <- [1,1,null,{"sessionId":"07ba864d-7294-467a-98a8-f369bfd4a926","capabilities":{"browserName":"firefox","browserVersion":"79.0a ... p/tmpF3k5Cq.mozrunner","moz:shutdownTimeout":180000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-06-12T01:03:12.179Z] 01:03:12 INFO - 1591923792177 Marionette DEBUG 69 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-06-12T01:03:12.180Z] 01:03:12 INFO - 1591923792178 Marionette DEBUG 69 <- [1,2,null,{"value":null}]
[task 2020-06-12T01:03:12.182Z] 01:03:12 INFO - 1591923792179 Marionette DEBUG 69 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-06-12T01:03:12.183Z] 01:03:12 INFO - 1591923792180 Marionette DEBUG 69 <- [1,3,null,{"value":null}]
[task 2020-06-12T01:03:12.183Z] 01:03:12 INFO - 1591923792181 Marionette DEBUG 69 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-06-12T01:03:12.184Z] 01:03:12 INFO - 1591923792182 Marionette DEBUG 69 <- [1,4,null,{"value":null}]
[task 2020-06-12T01:03:12.188Z] 01:03:12 INFO - 1591923792184 Marionette DEBUG 69 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2020-06-12T01:03:12.188Z] 01:03:12 INFO - 1591923792185 Marionette DEBUG 69 <- [1,5,null,{"value":"1"}]
[task 2020-06-12T01:03:12.189Z] 01:03:12 INFO - 1591923792186 Marionette DEBUG 69 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-06-12T01:03:12.189Z] 01:03:12 INFO - 1591923792186 Marionette DEBUG 69 <- [1,6,null,["1"]]
[task 2020-06-12T01:03:12.190Z] 01:03:12 INFO - 1591923792187 Marionette DEBUG 69 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2020-06-12T01:03:12.191Z] 01:03:12 INFO - 1591923792187 Marionette DEBUG 69 <- [1,7,null,{"value":"95"}]
[task 2020-06-12T01:03:12.192Z] 01:03:12 INFO - 1591923792189 Marionette DEBUG 69 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2020-06-12T01:03:12.192Z] 01:03:12 INFO - 1591923792190 Marionette DEBUG 69 <- [1,8,null,["95"]]
[task 2020-06-12T01:03:12.193Z] 01:03:12 INFO - 1591923792191 Marionette DEBUG 69 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2020-06-12T01:03:12.194Z] 01:03:12 INFO - 1591923792192 Marionette DEBUG 69 <- [1,9,null,["95"]]
[task 2020-06-12T01:03:12.197Z] 01:03:12 INFO - 1591923792194 Marionette DEBUG 69 -> [0,10,"WebDriver:SwitchToWindow",{"handle":"95","focus":true,"name":"95"}]
[task 2020-06-12T01:03:12.198Z] 01:03:12 INFO - 1591923792195 Marionette DEBUG 69 <- [1,10,null,{"value":null}]
[task 2020-06-12T01:03:12.199Z] 01:03:12 INFO - 1591923792195 Marionette DEBUG 69 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2020-06-12T01:03:12.200Z] 01:03:12 INFO - 1591923792196 Marionette DEBUG 69 <- [1,11,null,["95"]]
[task 2020-06-12T01:03:12.200Z] 01:03:12 INFO - 1591923792197 Marionette DEBUG 69 -> [0,12,"WebDriver:NewWindow",{"type":"tab","focus":false,"private":false}]
[task 2020-06-12T01:03:12.220Z] 01:03:12 INFO - 1591923792208 Marionette TRACE Received DOM event TabOpen for [object XULElement]
[task 2020-06-12T01:03:12.220Z] 01:03:12 INFO - 1591923792218 Marionette TRACE [111] Frame script loaded
[task 2020-06-12T01:03:12.284Z] 01:03:12 INFO - 1591923792276 Marionette DEBUG 69 <- [1,12,null,{"handle":"111","type":"tab"}]
[task 2020-06-12T01:03:12.284Z] 01:03:12 INFO - 1591923792277 Marionette TRACE [111] Frame script registered
[task 2020-06-12T01:03:12.300Z] 01:03:12 INFO - 1591923792291 Marionette DEBUG 69 -> [0,13,"WebDriver:GetWindowHandles",{}]
[task 2020-06-12T01:03:12.302Z] 01:03:12 INFO - 1591923792292 Marionette DEBUG 69 <- [1,13,null,["95","111"]]
[task 2020-06-12T01:03:12.303Z] 01:03:12 INFO - 1591923792295 Marionette DEBUG 69 -> [0,14,"WebDriver:GetWindowHandles",{}]
[task 2020-06-12T01:03:12.304Z] 01:03:12 INFO - 1591923792295 Marionette DEBUG 69 <- [1,14,null,["95","111"]]
[task 2020-06-12T01:03:12.305Z] 01:03:12 INFO - 1591923792300 Marionette DEBUG 69 -> [0,15,"WebDriver:SwitchToWindow",{"handle":"111","focus":true,"name":"111"}]
[task 2020-06-12T01:03:12.321Z] 01:03:12 INFO - 1591923792317 Marionette TRACE Received DOM event TabSelect for [object XULElement]
[task 2020-06-12T01:03:12.343Z] 01:03:12 INFO - 1591923792341 Marionette DEBUG 69 <- [1,15,null,{"value":null}]
[task 2020-06-12T01:03:12.358Z] 01:03:12 INFO - 1591923792347 Marionette DEBUG 69 -> [0,16,"WebDriver:Navigate",{"url":"http://127.0.0.1:33118/windowHandles.html"}]
[task 2020-06-12T01:03:12.359Z] 01:03:12 INFO - 1591923792356 Marionette TRACE [111] Received DOM event beforeunload for about:blank
[task 2020-06-12T01:03:12.394Z] 01:03:12 INFO - 1591923792387 Marionette TRACE [111] Received DOM event pagehide for about:blank
[task 2020-06-12T01:03:12.431Z] 01:03:12 INFO - 1591923792420 Marionette TRACE [111] Received DOM event DOMContentLoaded for http://127.0.0.1:33118/windowHandles.html
[task 2020-06-12T01:03:12.446Z] 01:03:12 INFO - 1591923792443 Marionette TRACE [111] Received DOM event pageshow for http://127.0.0.1:33118/windowHandles.html
[task 2020-06-12T01:03:12.465Z] 01:03:12 INFO - 1591923792455 Marionette DEBUG 69 <- [1,16,null,{"value":null}]
[task 2020-06-12T01:03:12.503Z] 01:03:12 INFO - 1591923792494 Marionette DEBUG 69 -> [0,17,"WebDriver:SwitchToWindow",{"handle":"95","focus":true,"name":"95"}]
[task 2020-06-12T01:03:12.518Z] 01:03:12 INFO - 1591923792506 Marionette TRACE Received DOM event TabSelect for [object XULElement]
[task 2020-06-12T01:03:12.534Z] 01:03:12 INFO - 1591923792525 Marionette DEBUG 69 <- [1,17,null,{"value":null}]
[task 2020-06-12T01:03:12.534Z] 01:03:12 INFO - 1591923792528 Marionette DEBUG 69 -> [0,18,"Marionette:GetContext",{}]
[task 2020-06-12T01:03:12.534Z] 01:03:12 INFO - 1591923792529 Marionette DEBUG 69 <- [1,18,null,{"value":"content"}]
[task 2020-06-12T01:03:12.542Z] 01:03:12 INFO - 1591923792535 Marionette DEBUG 69 -> [0,19,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-06-12T01:03:12.542Z] 01:03:12 INFO - 1591923792535 Marionette DEBUG 69 <- [1,19,null,{"value":null}]
[task 2020-06-12T01:03:12.542Z] 01:03:12 INFO - 1591923792537 Marionette DEBUG 69 -> [0,20,"WebDriver:ExecuteAsyncScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"tests/testing/marionette/h ... }, { once: true});\n win.gBrowser.discardBrowser(win.gBrowser.tabs[1]);","sandbox":"default","line":115}]
[task 2020-06-12T01:03:12.562Z] 01:03:12 INFO - 1591923792559 Marionette DEBUG 69 <- [1,20,null,{"value":true}]
[task 2020-06-12T01:03:12.570Z] 01:03:12 INFO - 1591923792566 Marionette DEBUG 69 -> [0,21,"Marionette:SetContext",{"value":"content"}]
[task 2020-06-12T01:03:12.570Z] 01:03:12 INFO - 1591923792566 Marionette DEBUG 69 <- [1,21,null,{"value":null}]
[task 2020-06-12T01:03:12.570Z] 01:03:12 INFO - 1591923792568 Marionette DEBUG 69 -> [0,22,"WebDriver:GetWindowHandles",{}]
[task 2020-06-12T01:03:12.570Z] 01:03:12 INFO - 1591923792569 Marionette DEBUG 69 <- [1,22,null,["95","111"]]
[task 2020-06-12T01:03:12.574Z] 01:03:12 INFO - 1591923792570 Marionette DEBUG 69 -> [0,23,"WebDriver:SwitchToWindow",{"handle":"111","focus":false,"name":"111"}]
[task 2020-06-12T01:03:12.574Z] 01:03:12 INFO - console.log: "[bug 1345098] Lazy browser prematurely inserted via 'messageManager' property access:\ngetter@chrome://browser/content/tabbrowser.js:2242:39\nget messageManager@chrome://marionette/content/browser.js:203:7\nswitchToTab@chrome://marionette/content/browser.js:505:5\nGeckoDriver.prototype.setWindowHandle@chrome://marionette/content/driver.js:1692:29\nGeckoDriver.prototype.switchToWindow@chrome://marionette/content/driver.js:1600:16\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-06-12T01:03:12.594Z] 01:03:12 INFO - 1591923792590 Marionette TRACE [113] Frame script loaded
[task 2020-06-12T01:03:12.594Z] 01:03:12 INFO - 1591923792591 Marionette DEBUG 69 <- [1,23,null,{"value":null}]
[task 2020-06-12T01:03:12.602Z] 01:03:12 INFO - 1591923792597 Marionette TRACE [113] Frame script registered
[task 2020-06-12T01:03:12.607Z] 01:03:12 INFO - Assertion failure

Flags: needinfo?(hskupin)
Whiteboard: [stockwell needswork:owner]

I will try to have a look at this failure this week.

In the last 7 days there have been 24 occurrences on mostly linux1804-64 opt.

Recent failure: https://treeherder.mozilla.org/logviewer.html#?job_id=311051511&repo=autoland

There have been 22 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-08-02&endday=2020-08-09&tree=trunk&bug=1559992

Affected platforms are linux1804-64 opt & debug, linux1804-64-asan, linux1804-64-shippable and windows10-64 debug.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=312471560&repo=autoland&lineNumber=39491

Whiteboard: [stockwell unknown] → [stockwell unknown][stockwell needswork:owner]

(In reply to Intermittent Failures Robot from comment #70)

Repository breakdown:

  • autoland: 12
  • try: 38
  • mozilla-central: 7
  • mozilla-release: 1

Most of the failures are on try and don't seem to be related to Marionette. Would it make sense to correct the classification?

https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-08-17&endday=2020-08-24&tree=all&bug=1559992

Flags: needinfo?(hskupin) → needinfo?(sheriffs)

I mailed the classifier of the Try failures over the weekend and they will stop doing many-to-many classifications.

Flags: needinfo?(sheriffs)
Whiteboard: [stockwell unknown][stockwell needswork:owner] → [stockwell needswork:owner]
Flags: needinfo?(hskupin)

The number of failures seem to have been dropped over the last days. Given that we also have more frequent failures like that for Mn jobs I would defer investigation here until the numbers grow again.

Flags: needinfo?(hskupin)

Looks like this test is no longer failing in CI since my patch from bug 1394354 landed. I will check back on Monday.

Depends on: 1394354

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

Looks like this test is no longer failing in CI since my patch from bug 1394354 landed. I will check back on Monday.

The test actually still fails but as it looks like it's Linux only and has a lower failure rate as compared to before. Lets revisit next week.

OS: Unspecified → Linux
Hardware: Unspecified → Desktop

We had 40 occurrences in the past week on Linux.
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=321786310&repo=mozilla-central&lineNumber=42683

Whiteboard: [stockwell unknown] → [stockwell needswork]

It looks like the spike of failures during the last days are all coming from enabling actors on non-Fission builds (bug 1669169). Lets make bug 1560015 a priority to fix.

There are 32 total failures in the last 7 days on linux1804-64 ebug and opt, linux1804-64-shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=323688462&repo=autoland&lineNumber=41809

[task 2020-12-06T06:41:37.194Z] 06:41:37 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py TestTabModalAlerts.test_handle_two_dialogs
[task 2020-12-06T06:41:37.194Z] 06:41:37 INFO - 1607236897189 Marionette DEBUG 21 <- [1,32,null,{"value":null}]
[task 2020-12-06T06:41:37.195Z] 06:41:37 INFO - 1607236897192 Marionette DEBUG Closed connection 21
[task 2020-12-06T06:41:37.196Z] 06:41:37 INFO - 1607236897195 Marionette DEBUG Accepted connection 22 from 127.0.0.1:51900
[task 2020-12-06T06:41:37.200Z] 06:41:37 INFO - 1607236897197 Marionette DEBUG 22 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-12-06T06:41:37.200Z] 06:41:37 INFO - 1607236897198 Marionette TRACE [15] Frame script loaded
[task 2020-12-06T06:41:37.202Z] 06:41:37 INFO - 1607236897199 Marionette DEBUG 22 <- [1,1,null,{"sessionId":"cc49e516-7239-4553-85ab-e5350e138f22","capabilities":{"browserName":"firefox","browserVersion":"85.0a ... mp/tmpI2OJFZ.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-12-06T06:41:37.202Z] 06:41:37 INFO - 1607236897200 Marionette DEBUG 22 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-12-06T06:41:37.205Z] 06:41:37 INFO - 1607236897201 Marionette DEBUG 22 <- [1,2,null,{"value":null}]
[task 2020-12-06T06:41:37.207Z] 06:41:37 INFO - 1607236897203 Marionette DEBUG 22 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-12-06T06:41:37.210Z] 06:41:37 INFO - 1607236897204 Marionette DEBUG 22 <- [1,3,null,{"value":null}]
[task 2020-12-06T06:41:37.211Z] 06:41:37 INFO - 1607236897205 Marionette DEBUG 22 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-12-06T06:41:37.212Z] 06:41:37 INFO - 1607236897206 Marionette DEBUG 22 <- [1,4,null,{"value":null}]
[task 2020-12-06T06:41:37.213Z] 06:41:37 INFO - 1607236897207 Marionette DEBUG 22 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2020-12-06T06:41:37.214Z] 06:41:37 INFO - 1607236897207 Marionette DEBUG 22 <- [1,5,null,{"value":"1"}]
[task 2020-12-06T06:41:37.214Z] 06:41:37 INFO - 1607236897209 Marionette DEBUG 22 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-12-06T06:41:37.215Z] 06:41:37 INFO - 1607236897209 Marionette DEBUG 22 <- [1,6,null,["1"]]
[task 2020-12-06T06:41:37.216Z] 06:41:37 INFO - 1607236897212 Marionette DEBUG 22 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2020-12-06T06:41:37.217Z] 06:41:37 INFO - 1607236897213 Marionette DEBUG 22 <- [1,7,null,{"value":"15"}]
[task 2020-12-06T06:41:37.221Z] 06:41:37 INFO - 1607236897217 Marionette DEBUG 22 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2020-12-06T06:41:37.221Z] 06:41:37 INFO - 1607236897218 Marionette DEBUG 22 <- [1,8,null,["15"]]
[task 2020-12-06T06:41:37.222Z] 06:41:37 INFO - 1607236897218 Marionette DEBUG 22 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2020-12-06T06:41:37.223Z] 06:41:37 INFO - 1607236897218 Marionette DEBUG 22 <- [1,9,null,["15"]]
[task 2020-12-06T06:41:37.223Z] 06:41:37 INFO - 1607236897219 Marionette DEBUG 22 -> [0,10,"WebDriver:NewWindow",{"type":"tab","focus":false,"private":false}]
[task 2020-12-06T06:41:37.230Z] 06:41:37 INFO - 1607236897226 Marionette TRACE Received DOM event TabOpen for [object XULElement]
[task 2020-12-06T06:41:37.230Z] 06:41:37 INFO - 1607236897229 Marionette TRACE [65] Frame script loaded
[task 2020-12-06T06:41:37.246Z] 06:41:37 INFO - 1607236897244 Marionette DEBUG 22 <- [1,10,null,{"handle":"65","type":"tab"}]
[task 2020-12-06T06:41:37.264Z] 06:41:37 INFO - 1607236897253 Marionette DEBUG 22 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2020-12-06T06:41:37.265Z] 06:41:37 INFO - 1607236897254 Marionette DEBUG 22 <- [1,11,null,["15","65"]]
[task 2020-12-06T06:41:37.266Z] 06:41:37 INFO - 1607236897254 Marionette DEBUG 22 -> [0,12,"WebDriver:GetWindowHandles",{}]
[task 2020-12-06T06:41:37.267Z] 06:41:37 INFO - 1607236897254 Marionette DEBUG 22 <- [1,12,null,["15","65"]]
[task 2020-12-06T06:41:37.269Z] 06:41:37 INFO - 1607236897255 Marionette DEBUG 22 -> [0,13,"WebDriver:SwitchToWindow",{"handle":"65","focus":true}]
[task 2020-12-06T06:41:37.270Z] 06:41:37 INFO - 1607236897259 Marionette TRACE Received DOM event TabSelect for [object XULElement]
[task 2020-12-06T06:41:37.279Z] 06:41:37 INFO - 1607236897270 Marionette DEBUG 22 <- [1,13,null,{"value":null}]
[task 2020-12-06T06:41:37.281Z] 06:41:37 INFO - 1607236897273 Marionette DEBUG 22 -> [0,14,"Marionette:GetContext",{}]
[task 2020-12-06T06:41:37.281Z] 06:41:37 INFO - 1607236897273 Marionette DEBUG 22 <- [1,14,null,{"value":"content"}]
[task 2020-12-06T06:41:37.281Z] 06:41:37 INFO - 1607236897273 Marionette DEBUG 22 -> [0,15,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-12-06T06:41:37.282Z] 06:41:37 INFO - 1607236897273 Marionette DEBUG 22 <- [1,15,null,{"value":null}]
[task 2020-12-06T06:41:37.282Z] 06:41:37 INFO - 1607236897274 Marionette DEBUG 22 -> [0,16,"WebDriver:ExecuteScript",{"script":"Components.utils.import("resource://gre/modules/Preferences.jsm");\n\n ... cified"],"filename":"../../venv/lib/python2.7/site-packages/marionette_driver/marionette.py","sandbox":"default","line":772}]
[task 2020-12-06T06:41:37.282Z] 06:41:37 INFO - 1607236897276 Marionette DEBUG 22 <- [1,16,null,{"value":true}]
[task 2020-12-06T06:41:37.283Z] 06:41:37 INFO - 1607236897278 Marionette DEBUG 22 -> [0,17,"Marionette:SetContext",{"value":"content"}]
[task 2020-12-06T06:41:37.284Z] 06:41:37 INFO - 1607236897278 Marionette DEBUG 22 <- [1,17,null,{"value":null}]
[task 2020-12-06T06:41:37.285Z] 06:41:37 INFO - 1607236897279 Marionette DEBUG 22 -> [0,18,"WebDriver:Navigate",{"url":"http://127.0.0.1:37639/test_tab_modal_dialogs.html"}]
[task 2020-12-06T06:41:37.302Z] 06:41:37 INFO - 1607236897292 Marionette TRACE Received event DOMContentLoaded for about:blank
[task 2020-12-06T06:41:37.302Z] 06:41:37 INFO - 1607236897295 Marionette TRACE Received event pageshow for about:blank
[task 2020-12-06T06:41:37.302Z] 06:41:37 INFO - 1607236897298 Marionette TRACE Received event beforeunload for about:blank
[task 2020-12-06T06:41:37.302Z] 06:41:37 INFO - 1607236897299 Marionette TRACE [65] Frame script unloaded
[task 2020-12-06T06:41:37.309Z] 06:41:37 INFO - 1607236897304 Marionette TRACE [65] Frame script loaded
[task 2020-12-06T06:41:37.309Z] 06:41:37 INFO - 1607236897306 Marionette TRACE Received event pagehide for about:blank
[task 2020-12-06T06:41:37.317Z] 06:41:37 INFO - 1607236897316 Marionette TRACE Detected remoteness change. New browsing context: 65
[task 2020-12-06T06:41:37.321Z] 06:41:37 INFO - 1607236897317 Marionette TRACE Received event beforeunload for about:blank
[task 2020-12-06T06:41:37.342Z] 06:41:37 INFO - 1607236897333 Marionette TRACE Received event pagehide for about:blank
[task 2020-12-06T06:41:37.347Z] 06:41:37 INFO - 1607236897341 Marionette TRACE Received event DOMContentLoaded for http://127.0.0.1:37639/test_tab_modal_dialogs.html
[task 2020-12-06T06:41:37.347Z] 06:41:37 INFO - 1607236897342 Marionette TRACE Received event pageshow for http://127.0.0.1:37639/test_tab_modal_dialogs.html
[task 2020-12-06T06:41:37.348Z] 06:41:37 INFO - 1607236897346 Marionette DEBUG 22 <- [1,18,null,{"value":null}]
[task 2020-12-06T06:41:37.365Z] 06:41:37 INFO - 1607236897355 Marionette DEBUG 22 -> [0,19,"WebDriver:FindElement",{"using":"id","value":"open-two-dialogs"}]
[task 2020-12-06T06:41:37.365Z] 06:41:37 INFO - 1607236897357 Marionette DEBUG 22 <- [1,19,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"96ac4611-804b-41e1-b400-7c52e1d216c4"}}]
[task 2020-12-06T06:41:37.365Z] 06:41:37 INFO - 1607236897358 Marionette DEBUG 22 -> [0,20,"WebDriver:ElementClick",{"id":"96ac4611-804b-41e1-b400-7c52e1d216c4"}]
[task 2020-12-06T06:41:37.381Z] 06:41:37 INFO - 1607236897376 Marionette TRACE Received observer notification tabmodal-dialog-loaded
[task 2020-12-06T06:41:37.382Z] 06:41:37 INFO - 1607236897376 Marionette TRACE Canceled page load listener because a dialog opened
[task 2020-12-06T06:41:37.383Z] 06:41:37 INFO - 1607236897377 Marionette DEBUG 22 <- [1,20,null,{"value":null}]
[task 2020-12-06T06:41:37.390Z] 06:41:37 INFO - 1607236897386 Marionette DEBUG 22 -> [0,21,"WebDriver:SendAlertText",{"text":"foo"}]
[task 2020-12-06T06:41:37.390Z] 06:41:37 INFO - 1607236897386 Marionette DEBUG 22 <- [1,21,null,{"value":null}]
[task 2020-12-06T06:41:37.390Z] 06:41:37 INFO - 1607236897387 Marionette DEBUG 22 -> [0,22,"WebDriver:AcceptAlert",{}]
[task 2020-12-06T06:41:37.391Z] 06:41:37 INFO - 1607236897389 Marionette TRACE Received event DOMModalDialogClosed
[task 2020-12-06T06:41:37.392Z] 06:41:37 INFO - 1607236897389 Marionette TRACE Received DOM event DOMModalDialogClosed for [object XULFrameElement]
[task 2020-12-06T06:41:37.400Z] 06:41:37 INFO - 1607236897393 Marionette DEBUG 22 <- [1,22,null,{"value":null}]
[task 2020-12-06T06:41:37.400Z] 06:41:37 INFO - 1607236897396 Marionette DEBUG 22 -> [0,23,"WebDriver:SendAlertText",{"text":"bar"}]
[task 2020-12-06T06:41:37.400Z] 06:41:37 INFO - 1607236897396 Marionette DEBUG 22 <- [1,23,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchAl ... t@chrome://marionette/content/server.js:241:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"},null]
[task 2020-12-06T06:41:37.400Z] 06:41:37 INFO - 1607236897397 Marionette DEBUG 22 -> [0,24,"Marionette:GetContext",{}]
[task 2020-12-06T06:41:37.400Z] 06:41:37 INFO - 1607236897397 Marionette DEBUG 22 <- [1,24,null,{"value":"content"}]
[task 2020-12-06T06:41:37.400Z] 06:41:37 INFO - 1607236897398 Marionette DEBUG 22 -> [0,25,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-12-06T06:41:37.400Z] 06:41:37 INFO - 1607236897398 Marionette DEBUG 22 <- [1,25,null,{"value":null}]
[task 2020-12-06T06:41:37.407Z] 06:41:37 INFO - 1607236897405 Marionette TRACE Received observer notification tabmodal-dialog-loaded
[task 2020-12-06T06:41:37.411Z] 06:41:37 INFO - 1607236897409 Marionette DEBUG 22 -> [0,26,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2020-12-06T06:41:37.429Z] 06:41:37 INFO - 1607236897417 Marionette TRACE Received event DOMModalDialogClosed
[task 2020-12-06T06:41:37.430Z] 06:41:37 INFO - 1607236897417 Marionette TRACE Received DOM event DOMModalDialogClosed for [object XULFrameElement]
[task 2020-12-06T06:41:37.430Z] 06:41:37 INFO - 1607236897419 Marionette TRACE Received DOM event click for http://127.0.0.1:37639/test_tab_modal_dialogs.html#
[task 2020-12-06T06:41:37.431Z] 06:41:37 INFO - DEBUG: Adding blocker UserInteractionTimer 8 for document 7ff0b7a75000 for phase xpcom-will-shutdown
[task 2020-12-06T06:41:37.437Z] 06:41:37 INFO - 1607236897431 Marionette DEBUG 22 <- [1,26,{"error":"unexpected alert open","message":"Dismissed user prompt dialog: Second","stacktrace":"WebDriverError@chrome:/ ... ette/content/error.js:466:5\nGeckoDriver.prototype._handleUserPrompts@chrome://marionette/content/driver.js:3527:13\n"},null]
[task 2020-12-06T06:41:37.437Z] 06:41:37 INFO - 1607236897435 Marionette DEBUG 22 -> [0,27,"Marionette:SetContext",{"value":"content"}]
[task 2020-12-06T06:41:37.438Z] 06:41:37 INFO - 1607236897435 Marionette DEBUG 22 <- [1,27,null,{"value":null}]
[task 2020-12-06T06:41:37.438Z] 06:41:37 WARNING - Failed to gather test failure debug: Dismissed user prompt dialog: Second
[task 2020-12-06T06:41:37.438Z] 06:41:37 WARNING - stacktrace:
[task 2020-12-06T06:41:37.438Z] 06:41:37 WARNING - WebDriverError@chrome://marionette/content/error.js:181:5
[task 2020-12-06T06:41:37.438Z] 06:41:37 WARNING - UnexpectedAlertOpenError@chrome://marionette/content/error.js:466:5
[task 2020-12-06T06:41:37.438Z] 06:41:37 WARNING - GeckoDriver.prototype._handleUserPrompts@chrome://marionette/content/driver.js:3527:13
[task 2020-12-06T06:41:37.439Z] 06:41:37 WARNING -
[task 2020-12-06T06:41:37.439Z] 06:41:37 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py TestTabModalAlerts.test_handle_two_dialogs | NoAlertPresentException:
[task 2020-12-06T06:41:37.440Z] 06:41:37 INFO - stacktrace:
[task 2020-12-06T06:41:37.440Z] 06:41:37 INFO - WebDriverError@chrome://marionette/content/error.js:181:5
[task 2020-12-06T06:41:37.441Z] 06:41:37 INFO - NoSuchAlertError@chrome://marionette/content/error.js:382:5
[task 2020-12-06T06:41:37.442Z] 06:41:37 INFO - GeckoDriver.prototype._checkIfAlertIsPresent@chrome://marionette/content/driver.js:3498:11
[task 2020-12-06T06:41:37.442Z] 06:41:37 INFO - GeckoDriver.prototype.sendKeysToDialog@chrome://marionette/content/driver.js:3471:8
[task 2020-12-06T06:41:37.443Z] 06:41:37 INFO - despatch@chrome://marionette/content/server.js:297:40
[task 2020-12-06T06:41:37.444Z] 06:41:37 INFO - execute@chrome://marionette/content/server.js:267:16
[task 2020-12-06T06:41:37.444Z] 06:41:37 INFO - onPacket/<@chrome://marionette/content/server.js:240:20
[task 2020-12-06T06:41:37.444Z] 06:41:37 INFO - onPacket@chrome://marionette/content/server.js:241:9
[task 2020-12-06T06:41:37.444Z] 06:41:37 INFO - _onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20
[task 2020-12-06T06:41:37.445Z] 06:41:37 INFO - Traceback (most recent call last):
[task 2020-12-06T06:41:37.445Z] 06:41:37 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 214, in run
[task 2020-12-06T06:41:37.446Z] 06:41:37 INFO - testMethod()
[task 2020-12-06T06:41:37.446Z] 06:41:37 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py", line 158, in test_handle_two_dialogs
[task 2020-12-06T06:41:37.446Z] 06:41:37 INFO - alert2.send_keys("bar")
[task 2020-12-06T06:41:37.447Z] 06:41:37 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 395, in send_keys
[task 2020-12-06T06:41:37.447Z] 06:41:37 INFO - "WebDriver:SendAlertText", {"text": Marionette.convert_keys(*string)}
[task 2020-12-06T06:41:37.448Z] 06:41:37 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2020-12-06T06:41:37.448Z] 06:41:37 INFO - return func(*args, **kwargs)
[task 2020-12-06T06:41:37.449Z] 06:41:37 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 625, in _send_message
[task 2020-12-06T06:41:37.449Z] 06:41:37 INFO - self._handle_error(err)
[task 2020-12-06T06:41:37.449Z] 06:41:37 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 647, in _handle_error
[task 2020-12-06T06:41:37.450Z] 06:41:37 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2020-12-06T06:41:37.450Z] 06:41:37 INFO - TEST-INFO took 245ms
[task 2020-12-06T06:41:37.463Z] 06:41:37 INFO - 1607236897451 Marionette DEBUG 22 -> [0,28,"WebDriver:DismissAlert",{}]
[task 2020-12-06T06:41:37.465Z] 06:41:37 INFO - 1607236897452 Marionette DEBUG 22 <- [1,28,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchAl ... t@chrome://marionette/content/server.js:241:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"},null]
[task 2020-12-06T06:41:37.466Z] 06:41:37 INFO - 1607236897453 Marionette DEBUG 22 -> [0,29,"WebDriver:GetWindowHandles",{}]
[task 2020-12-06T06:41:37.466Z] 06:41:37 INFO - 1607236897453 Marionette DEBUG 22 <- [1,29,null,["15","65"]]
[task 2020-12-06T06:41:37.466Z] 06:41:37 INFO - 1607236897454 Marionette DEBUG 22 -> [0,30,"WebDriver:SwitchToWindow",{"handle":"65","focus":true}]
[task 2020-12-06T06:41:37.467Z] 06:41:37 INFO - 1607236897454 Marionette DEBUG 22 <- [1,30,null,{"value":null}]
[task 2020-12-06T06:41:37.467Z] 06:41:37 INFO - 1607236897454 Marionette DEBUG 22 -> [0,31,"WebDriver:CloseWindow",{}]
[task 2020-12-06T06:41:37.467Z] 06:41:37 INFO - 1607236897459 Marionette TRACE Received DOM event TabClose for [object XULElement]
[task 2020-12-06T06:41:37.468Z] 06:41:37 INFO - 1607236897459 Marionette TRACE Received DOM event TabClose for [object XULElement]
[task 2020-12-06T06:41:37.468Z] 06:41:37 INFO - 1607236897461 Marionette TRACE [65] Frame script unloaded
[task 2020-12-06T06:41:37.483Z] 06:41:37 INFO - 1607236897473 Marionette TRACE Received observer notification message-manager-disconnect
[task 2020-12-06T06:41:37.483Z] 06:41:37 INFO - 1607236897473 Marionette TRACE Received observer notification message-manager-disconnect
[task 2020-12-06T06:41:37.483Z] 06:41:37 INFO - 1607236897473 Marionette DEBUG 22 <- [1,31,null,["15"]]
[task 2020-12-06T06:41:37.485Z] 06:41:37 INFO - 1607236897474 Marionette DEBUG 22 -> [0,32,"WebDriver:SwitchToWindow",{"handle":"15","focus":true}]
[task 2020-12-06T06:41:37.486Z] 06:41:37 INFO - 1607236897475 Marionette DEBUG 22 <- [1,32,null,{"value":null}]
[task 2020-12-06T06:41:37.487Z] 06:41:37 INFO - 1607236897475 Marionette DEBUG 22 -> [0,33,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-12-06T06:41:37.487Z] 06:41:37 INFO - 1607236897475 Marionette DEBUG 22 <- [1,33,null,["1"]]
[task 2020-12-06T06:41:37.487Z] 06:41:37 INFO - 1607236897476 Marionette DEBUG 22 -> [0,34,"WebDriver:GetWindowHandles",{}]
[task 2020-12-06T06:41:37.488Z] 06:41:37 INFO - 1607236897476 Marionette DEBUG 22 <- [1,34,null,["15"]]
[task 2020-12-06T06:41:37.488Z] 06:41:37 INFO - 1607236897478 Marionette DEBUG 22 -> [0,35,"WebDriver:DeleteSession",{}]
[task 2020-12-06T06:41:37.489Z] 06:41:37 INFO - 1607236897480 Marionette DEBUG 22 <- [1,35,null,{"value":null}]

Henrik can you take a look?

Flags: needinfo?(hskupin)
Whiteboard: [stockwell needswork] → [stockwell needswork:owner]

There are 32 total failures in the last 7 days on

  • linux1804-64 debug and opt
  • linux1804-64-asan opt
  • linux1804-64-shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=329325548&repo=autoland&lineNumber=43723

[task 2021-02-09T09:40:50.283Z] 09:40:50 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py TestTabModalAlerts.test_handle_two_dialogs
[task 2021-02-09T09:40:50.545Z] 09:40:50 INFO - 1612863650544 Marionette DEBUG Accepted connection 22 from 127.0.0.1:60114
[task 2021-02-09T09:40:50.549Z] 09:40:50 INFO - 1612863650545 Marionette DEBUG Closed connection 21
[task 2021-02-09T09:40:50.550Z] 09:40:50 INFO - 1612863650546 Marionette TRACE Canceled page load listener because no navigation has been detected
[task 2021-02-09T09:40:50.570Z] 09:40:50 INFO - 1612863650563 Marionette DEBUG 22 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-02-09T09:40:50.571Z] 09:40:50 INFO - 1612863650565 Marionette DEBUG 22 <- [1,1,null,{"sessionId":"4f36cbd9-0aed-4233-9fc7-43f0398c707e","capabilities":{"browserName":"firefox","browserVersion":"87.0a ... mp/tmpgpIp2q.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2021-02-09T09:40:50.586Z] 09:40:50 INFO - 1612863650581 Marionette DEBUG 22 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2021-02-09T09:40:50.586Z] 09:40:50 INFO - 1612863650581 Marionette DEBUG 22 <- [1,2,null,{"value":null}]
[task 2021-02-09T09:40:50.594Z] 09:40:50 INFO - 1612863650588 Marionette DEBUG 22 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2021-02-09T09:40:50.594Z] 09:40:50 INFO - 1612863650589 Marionette DEBUG 22 <- [1,3,null,{"value":null}]
[task 2021-02-09T09:40:50.594Z] 09:40:50 INFO - 1612863650590 Marionette DEBUG 22 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2021-02-09T09:40:50.594Z] 09:40:50 INFO - 1612863650590 Marionette DEBUG 22 <- [1,4,null,{"value":null}]
[task 2021-02-09T09:40:50.595Z] 09:40:50 INFO - 1612863650592 Marionette DEBUG 22 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2021-02-09T09:40:50.596Z] 09:40:50 INFO - 1612863650593 Marionette DEBUG 22 <- [1,5,null,{"value":"1"}]
[task 2021-02-09T09:40:50.597Z] 09:40:50 INFO - 1612863650594 Marionette DEBUG 22 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2021-02-09T09:40:50.597Z] 09:40:50 INFO - 1612863650595 Marionette DEBUG 22 <- [1,6,null,["1"]]
[task 2021-02-09T09:40:50.600Z] 09:40:50 INFO - 1612863650598 Marionette DEBUG 22 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2021-02-09T09:40:50.600Z] 09:40:50 INFO - 1612863650599 Marionette DEBUG 22 <- [1,7,null,{"value":"15"}]
[task 2021-02-09T09:40:50.601Z] 09:40:50 INFO - 1612863650600 Marionette DEBUG 22 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2021-02-09T09:40:50.603Z] 09:40:50 INFO - 1612863650600 Marionette DEBUG 22 <- [1,8,null,["15"]]
[task 2021-02-09T09:40:50.606Z] 09:40:50 INFO - 1612863650603 Marionette DEBUG 22 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2021-02-09T09:40:50.606Z] 09:40:50 INFO - 1612863650603 Marionette DEBUG 22 <- [1,9,null,["15"]]
[task 2021-02-09T09:40:50.606Z] 09:40:50 INFO - 1612863650604 Marionette DEBUG 22 -> [0,10,"WebDriver:NewWindow",{"type":"tab","focus":false,"private":false}]
[task 2021-02-09T09:40:50.625Z] 09:40:50 INFO - 1612863650616 Marionette TRACE Received DOM event TabOpen for [object XULElement]
[task 2021-02-09T09:40:50.640Z] 09:40:50 INFO - [Parent 9869, Main Thread] WARNING: '!mLastFocusedWindow', file /builds/worker/checkouts/gecko/widget/gtk/IMContextWrapper.cpp:3104
[task 2021-02-09T09:40:50.640Z] 09:40:50 INFO - 1612863650628 Marionette TRACE [65] MarionetteEvents actor created for window id 88
[task 2021-02-09T09:40:50.684Z] 09:40:50 INFO - 1612863650680 Marionette TRACE Received event beforeunload for about:blank
[task 2021-02-09T09:40:50.699Z] 09:40:50 INFO - 1612863650695 Marionette TRACE Received event pagehide for about:blank
[task 2021-02-09T09:40:50.715Z] 09:40:50 INFO - 1612863650707 Marionette TRACE [65] MarionetteEvents actor created for window id 8589934603
[task 2021-02-09T09:40:50.716Z] 09:40:50 INFO - 1612863650708 Marionette TRACE Received event DOMContentLoaded for about:blank
[task 2021-02-09T09:40:50.719Z] 09:40:50 INFO - 1612863650716 Marionette TRACE Received event pageshow for about:blank
[task 2021-02-09T09:40:50.720Z] 09:40:50 INFO - 1612863650717 Marionette DEBUG 22 <- [1,10,null,{"handle":"65","type":"tab"}]
[task 2021-02-09T09:40:50.735Z] 09:40:50 INFO - 1612863650729 Marionette DEBUG 22 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2021-02-09T09:40:50.736Z] 09:40:50 INFO - 1612863650729 Marionette DEBUG 22 <- [1,11,null,["15","65"]]
[task 2021-02-09T09:40:50.737Z] 09:40:50 INFO - 1612863650731 Marionette DEBUG 22 -> [0,12,"WebDriver:GetWindowHandles",{}]
[task 2021-02-09T09:40:50.737Z] 09:40:50 INFO - 1612863650731 Marionette DEBUG 22 <- [1,12,null,["15","65"]]
[task 2021-02-09T09:40:50.738Z] 09:40:50 INFO - 1612863650732 Marionette DEBUG 22 -> [0,13,"WebDriver:SwitchToWindow",{"handle":"65","focus":true}]
[task 2021-02-09T09:40:50.745Z] 09:40:50 INFO - [Parent 9869, Main Thread] WARNING: '!mLastFocusedWindow', file /builds/worker/checkouts/gecko/widget/gtk/IMContextWrapper.cpp:3104
[task 2021-02-09T09:40:50.746Z] 09:40:50 INFO - 1612863650744 Marionette TRACE Received DOM event TabSelect for [object XULElement]
[task 2021-02-09T09:40:50.762Z] 09:40:50 INFO - 1612863650756 Marionette DEBUG 22 <- [1,13,null,{"value":null}]
[task 2021-02-09T09:40:50.763Z] 09:40:50 INFO - 1612863650761 Marionette DEBUG 22 -> [0,14,"WebDriver:Navigate",{"url":"http://127.0.0.1:33932/test_tab_modal_dialogs.html"}]
[task 2021-02-09T09:40:50.767Z] 09:40:50 INFO - 1612863650764 Marionette TRACE [65] MarionetteCommands actor created for window id 8589934603
[task 2021-02-09T09:40:50.775Z] 09:40:50 INFO - 1612863650769 Marionette TRACE Received event beforeunload for about:blank
[task 2021-02-09T09:40:50.811Z] 09:40:50 INFO - 1612863650808 Marionette TRACE Received event pagehide for about:blank
[task 2021-02-09T09:40:50.826Z] 09:40:50 INFO - 1612863650825 Marionette TRACE [65] MarionetteEvents actor created for window id 90
[task 2021-02-09T09:40:50.834Z] 09:40:50 INFO - 1612863650830 Marionette TRACE Received event beforeunload for about:blank
[task 2021-02-09T09:40:50.849Z] 09:40:50 INFO - 1612863650845 Marionette TRACE Received event pagehide for about:blank
[task 2021-02-09T09:40:50.870Z] 09:40:50 INFO - 1612863650868 Marionette TRACE [65] MarionetteEvents actor created for window id 6442450963
[task 2021-02-09T09:40:50.890Z] 09:40:50 INFO - 1612863650884 Marionette TRACE Received event DOMContentLoaded for http://127.0.0.1:33932/test_tab_modal_dialogs.html
[task 2021-02-09T09:40:50.891Z] 09:40:50 INFO - 1612863650885 Marionette TRACE Received event pageshow for http://127.0.0.1:33932/test_tab_modal_dialogs.html
[task 2021-02-09T09:40:50.906Z] 09:40:50 INFO - 1612863650898 Marionette DEBUG 22 <- [1,14,null,{"value":null}]
[task 2021-02-09T09:40:50.921Z] 09:40:50 INFO - 1612863650917 Marionette DEBUG 22 -> [0,15,"WebDriver:FindElement",{"using":"id","value":"open-two-dialogs"}]
[task 2021-02-09T09:40:50.922Z] 09:40:50 INFO - 1612863650919 Marionette TRACE [65] MarionetteCommands actor created for window id 6442450963
[task 2021-02-09T09:40:50.937Z] 09:40:50 INFO - 1612863650931 Marionette DEBUG 22 <- [1,15,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"3910ad58-bd9a-421b-82ea-dfdde7ddfff7"}}]
[task 2021-02-09T09:40:50.937Z] 09:40:50 INFO - 1612863650933 Marionette DEBUG 22 -> [0,16,"WebDriver:ElementClick",{"id":"3910ad58-bd9a-421b-82ea-dfdde7ddfff7"}]
[task 2021-02-09T09:40:50.973Z] 09:40:50 INFO - [Child 9997, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2021-02-09T09:40:50.973Z] 09:40:50 INFO - [Child 9997, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2021-02-09T09:40:50.981Z] 09:40:50 INFO - [Parent 9869, Main Thread] WARNING: '!mLastFocusedWindow', file /builds/worker/checkouts/gecko/widget/gtk/IMContextWrapper.cpp:3104
[task 2021-02-09T09:40:50.981Z] 09:40:50 INFO - 1612863650977 Marionette TRACE Received observer notification tabmodal-dialog-loaded
[task 2021-02-09T09:40:50.981Z] 09:40:50 INFO - 1612863650977 Marionette TRACE Received observer notification tabmodal-dialog-loaded
[task 2021-02-09T09:40:50.981Z] 09:40:50 INFO - 1612863650977 Marionette TRACE Canceled page load listener because a dialog opened
[task 2021-02-09T09:40:50.981Z] 09:40:50 INFO - 1612863650978 Marionette DEBUG 22 <- [1,16,null,{"value":null}]
[task 2021-02-09T09:40:50.996Z] 09:40:50 INFO - 1612863650995 Marionette DEBUG 22 -> [0,17,"WebDriver:SendAlertText",{"text":"foo"}]
[task 2021-02-09T09:40:50.997Z] 09:40:50 INFO - 1612863650995 Marionette DEBUG 22 <- [1,17,null,{"value":null}]
[task 2021-02-09T09:40:51.001Z] 09:40:51 INFO - 1612863650998 Marionette DEBUG 22 -> [0,18,"WebDriver:AcceptAlert",{}]
[task 2021-02-09T09:40:51.002Z] 09:40:51 INFO - [Parent 9869, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-02-09T09:40:51.005Z] 09:40:51 INFO - 1612863651003 Marionette TRACE Received event DOMModalDialogClosed
[task 2021-02-09T09:40:51.007Z] 09:40:51 INFO - 1612863651004 Marionette TRACE Received event DOMModalDialogClosed
[task 2021-02-09T09:40:51.007Z] 09:40:51 INFO - 1612863651004 Marionette TRACE Received DOM event DOMModalDialogClosed for [object XULFrameElement]
[task 2021-02-09T09:40:51.016Z] 09:40:51 INFO - 1612863651009 Marionette DEBUG 22 <- [1,18,null,{"value":null}]
[task 2021-02-09T09:40:51.016Z] 09:40:51 INFO - 1612863651014 Marionette DEBUG 22 -> [0,19,"WebDriver:SendAlertText",{"text":"bar"}]
[task 2021-02-09T09:40:51.018Z] 09:40:51 INFO - 1612863651015 Marionette DEBUG 22 <- [1,19,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchAl ... t@chrome://marionette/content/server.js:241:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"},null]
[task 2021-02-09T09:40:51.038Z] 09:40:51 INFO - [Parent 9869, Main Thread] WARNING: '!mLastFocusedWindow', file /builds/worker/checkouts/gecko/widget/gtk/IMContextWrapper.cpp:3104
[task 2021-02-09T09:40:51.038Z] 09:40:51 INFO - 1612863651034 Marionette TRACE Received observer notification tabmodal-dialog-loaded
[task 2021-02-09T09:40:51.038Z] 09:40:51 INFO - 1612863651034 Marionette TRACE Received observer notification tabmodal-dialog-loaded
[task 2021-02-09T09:40:51.077Z] 09:40:51 INFO - 1612863651067 Marionette DEBUG 22 -> [0,20,"Marionette:GetContext",{}]
[task 2021-02-09T09:40:51.077Z] 09:40:51 INFO - 1612863651067 Marionette DEBUG 22 <- [1,20,null,{"value":"content"}]
[task 2021-02-09T09:40:51.079Z] 09:40:51 INFO - 1612863651068 Marionette DEBUG 22 -> [0,21,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-02-09T09:40:51.079Z] 09:40:51 INFO - 1612863651068 Marionette DEBUG 22 <- [1,21,null,{"value":null}]
[task 2021-02-09T09:40:51.080Z] 09:40:51 INFO - 1612863651069 Marionette DEBUG 22 -> [0,22,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2021-02-09T09:40:51.081Z] 09:40:51 INFO - [Parent 9869, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-02-09T09:40:51.083Z] 09:40:51 INFO - 1612863651074 Marionette TRACE Received event DOMModalDialogClosed
[task 2021-02-09T09:40:51.084Z] 09:40:51 INFO - 1612863651075 Marionette TRACE Received event DOMModalDialogClosed
[task 2021-02-09T09:40:51.084Z] 09:40:51 INFO - 1612863651075 Marionette TRACE Received DOM event DOMModalDialogClosed for [object XULFrameElement]
[task 2021-02-09T09:40:51.101Z] 09:40:51 INFO - 1612863651088 Marionette TRACE Received DOM event click for http://127.0.0.1:33932/test_tab_modal_dialogs.html#
[task 2021-02-09T09:40:51.102Z] 09:40:51 INFO - 1612863651095 Marionette DEBUG 22 <- [1,22,{"error":"unexpected alert open","message":"Dismissed user prompt dialog: Second","stacktrace":"WebDriverError@chrome:/ ... ette/content/error.js:466:5\nGeckoDriver.prototype._handleUserPrompts@chrome://marionette/content/driver.js:3501:13\n"},null]
[task 2021-02-09T09:40:51.119Z] 09:40:51 INFO - DEBUG: Adding blocker UserInteractionTimer 8 for document 7fa2a637f000 for phase xpcom-will-shutdown
[task 2021-02-09T09:40:51.135Z] 09:40:51 INFO - 1612863651132 Marionette DEBUG 22 -> [0,23,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-09T09:40:51.139Z] 09:40:51 WARNING - Failed to gather test failure debug: Dismissed user prompt dialog: Second
[task 2021-02-09T09:40:51.140Z] 09:40:51 WARNING - stacktrace:
[task 2021-02-09T09:40:51.140Z] 09:40:51 WARNING - WebDriverError@chrome://marionette/content/error.js:181:5
[task 2021-02-09T09:40:51.142Z] 09:40:51 WARNING - UnexpectedAlertOpenError@chrome://marionette/content/error.js:466:5
[task 2021-02-09T09:40:51.145Z] 09:40:51 WARNING - GeckoDriver.prototype._handleUserPrompts@chrome://marionette/content/driver.js:3501:13
[task 2021-02-09T09:40:51.146Z] 09:40:51 WARNING -
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py TestTabModalAlerts.test_handle_two_dialogs | NoAlertPresentException:
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - stacktrace:
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - WebDriverError@chrome://marionette/content/error.js:181:5
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - NoSuchAlertError@chrome://marionette/content/error.js:382:5
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - GeckoDriver.prototype._checkIfAlertIsPresent@chrome://marionette/content/driver.js:3472:11
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - GeckoDriver.prototype.sendKeysToDialog@chrome://marionette/content/driver.js:3445:8
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - despatch@chrome://marionette/content/server.js:297:40
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - execute@chrome://marionette/content/server.js:267:16
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - onPacket/<@chrome://marionette/content/server.js:240:20
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - onPacket@chrome://marionette/content/server.js:241:9
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - _onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - Traceback (most recent call last):
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 214, in run
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - testMethod()
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_modal_dialogs.py", line 152, in test_handle_two_dialogs
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - alert2.send_keys("bar")
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 399, in send_keys
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - "WebDriver:SendAlertText", {"text": Marionette.convert_keys(*string)}
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - return func(*args, **kwargs)
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 629, in _send_message
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - self._handle_error(err)
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 651, in _handle_error
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - TEST-INFO took 852ms
[task 2021-02-09T09:40:51.153Z] 09:40:51 INFO - 1612863651133 Marionette DEBUG 22 <- [1,23,null,{"value":null}]
[task 2021-02-09T09:40:51.156Z] 09:40:51 INFO - 1612863651151 Marionette DEBUG 22 -> [0,24,"WebDriver:DismissAlert",{}]
[task 2021-02-09T09:40:51.156Z] 09:40:51 INFO - 1612863651152 Marionette DEBUG 22 <- [1,24,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchAl ... t@chrome://marionette/content/server.js:241:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"},null]
[task 2021-02-09T09:40:51.157Z] 09:40:51 INFO - 1612863651155 Marionette DEBUG 22 -> [0,25,"WebDriver:GetWindowHandles",{}]
[task 2021-02-09T09:40:51.158Z] 09:40:51 INFO - 1612863651157 Marionette DEBUG 22 <- [1,25,null,["15","65"]]
[task 2021-02-09T09:40:51.162Z] 09:40:51 INFO - 1612863651159 Marionette DEBUG 22 -> [0,26,"WebDriver:SwitchToWindow",{"handle":"65","focus":true}]
[task 2021-02-09T09:40:51.162Z] 09:40:51 INFO - 1612863651160 Marionette DEBUG 22 <- [1,26,null,{"value":null}]
[task 2021-02-09T09:40:51.169Z] 09:40:51 INFO - 1612863651166 Marionette DEBUG 22 -> [0,27,"WebDriver:CloseWindow",{}]
[task 2021-02-09T09:40:51.187Z] 09:40:51 INFO - 1612863651181 Marionette TRACE Received DOM event TabClose for [object XULElement]
[task 2021-02-09T09:40:51.214Z] 09:40:51 INFO - 1612863651207 Marionette TRACE Canceled page load listener because no navigation has been detected
[task 2021-02-09T09:40:51.222Z] 09:40:51 INFO - 1612863651216 Marionette TRACE Received observer notification message-manager-disconnect
[task 2021-02-09T09:40:51.222Z] 09:40:51 INFO - 1612863651216 Marionette DEBUG 22 <- [1,27,null,["15"]]
[task 2021-02-09T09:40:51.223Z] 09:40:51 INFO - 1612863651220 Marionette DEBUG 22 -> [0,28,"WebDriver:SwitchToWindow",{"handle":"15","focus":true}]
[task 2021-02-09T09:40:51.226Z] 09:40:51 INFO - 1612863651221 Marionette DEBUG 22 <- [1,28,null,{"value":null}]

Henrik are there any updates here?

Flags: needinfo?(hskupin)
Flags: needinfo?(hskupin)
Whiteboard: [stockwell unknown] → [stockwell needswork:owner]

As it looks like with the work on bug 1686741 I can more easily reproduce this failure at least in CI. It might help us to get this problem fixed.

Depends on: 1686741
Flags: needinfo?(hskupin)

The second alert is not expected to immediately be created by the
browser. As such the test has to wait for it.

Depends on D105316

Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/cbcdbd4acdfb
[marionette] Fix test_modal_dialogs.py TestTabModalAlerts.test_handle_two_dialogs. r=marionette-reviewers,jgraham
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 87 Branch
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.

Attachment

General

Created:
Updated:
Size: