Closed Bug 1631204 Opened 5 years ago Closed 5 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_unhandled_prompt_behavior.py <random> | AssertionError: False != True

Categories

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

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

Tracking

(firefox76 unaffected, firefox77 wontfix, firefox78 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla78
Tracking Flags:
Tracking Status
firefox76 --- unaffected
firefox77 --- wontfix
firefox78 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=298229354&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/CKedv7OIRfCbQ5i85j6G0w/runs/0/artifacts/public/logs/live_backing.log

[task 2020-04-18T11:33:47.624Z] 11:33:47 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_unhandled_prompt_behavior.py TestUnhandledPromptBehavior.test_ignore_prompt
[task 2020-04-18T11:33:47.626Z] 11:33:47 INFO - 1587209627625 Marionette DEBUG Closed connection 66
[task 2020-04-18T11:33:47.628Z] 11:33:47 INFO - 1587209627626 Marionette DEBUG Accepted connection 67 from 127.0.0.1:52968
[task 2020-04-18T11:33:47.628Z] 11:33:47 INFO - 1587209627627 Marionette DEBUG 67 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-04-18T11:33:47.630Z] 11:33:47 INFO - 1587209627628 Marionette TRACE [4] Frame script loaded
[task 2020-04-18T11:33:47.630Z] 11:33:47 INFO - 1587209627629 Marionette TRACE [4] Frame script registered
[task 2020-04-18T11:33:47.632Z] 11:33:47 INFO - 1587209627630 Marionette DEBUG 67 <- [1,1,null,{"sessionId":"13225e5a-1e77-4e73-9f2d-52d521616258","capabilities":{"browserName":"firefox","browserVersion":"77.0a ... p\tmp7vkcic.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-04-18T11:33:47.632Z] 11:33:47 INFO - 1587209627631 Marionette DEBUG 67 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-04-18T11:33:47.634Z] 11:33:47 INFO - 1587209627631 Marionette DEBUG 67 <- [1,2,null,{"value":null}]
[task 2020-04-18T11:33:47.634Z] 11:33:47 INFO - 1587209627632 Marionette DEBUG 67 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-04-18T11:33:47.634Z] 11:33:47 INFO - 1587209627633 Marionette DEBUG 67 <- [1,3,null,{"value":null}]
[task 2020-04-18T11:33:47.636Z] 11:33:47 INFO - 1587209627633 Marionette DEBUG 67 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-04-18T11:33:47.636Z] 11:33:47 INFO - 1587209627634 Marionette DEBUG 67 <- [1,4,null,{"value":null}]
[task 2020-04-18T11:33:47.636Z] 11:33:47 INFO - 1587209627635 Marionette DEBUG 67 -> [0,5,"WebDriver:DeleteSession",{}]
[task 2020-04-18T11:33:47.638Z] 11:33:47 INFO - 1587209627636 Marionette DEBUG 67 <- [1,5,null,{"value":null}]
[task 2020-04-18T11:33:47.640Z] 11:33:47 INFO - 1587209627638 Marionette DEBUG Closed connection 67
[task 2020-04-18T11:33:47.640Z] 11:33:47 INFO - 1587209627639 Marionette DEBUG Accepted connection 68 from 127.0.0.1:52969
[task 2020-04-18T11:33:47.642Z] 11:33:47 INFO - 1587209627640 Marionette DEBUG 68 -> [0,1,"WebDriver:NewSession",{"unhandledPromptBehavior":"ignore"}]
[task 2020-04-18T11:33:47.644Z] 11:33:47 INFO - 1587209627641 Marionette TRACE [4] Frame script loaded
[task 2020-04-18T11:33:47.644Z] 11:33:47 INFO - 1587209627642 Marionette TRACE [4] Frame script registered
[task 2020-04-18T11:33:47.644Z] 11:33:47 INFO - 1587209627643 Marionette DEBUG 68 <- [1,1,null,{"sessionId":"52a49508-1f58-42a8-aa07-be532cd51c77","capabilities":{"browserName":"firefox","browserVersion":"77.0a ... p\tmp7vkcic.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-04-18T11:33:47.646Z] 11:33:47 INFO - 1587209627644 Marionette DEBUG 68 -> [0,2,"WebDriver:ExecuteAsyncScript",{"scriptTimeout":null,"newSandbox":true,"args":["prompt","foo prompt"],"filename":"Z:\ta ... .return_value = null;\n window.return_value = windowarguments[0];","sandbox":"default","line":45}]
[task 2020-04-18T11:33:47.656Z] 11:33:47 INFO - 1587209627653 Marionette TRACE Received observer notification tabmodal-dialog-loaded
[task 2020-04-18T11:33:47.656Z] 11:33:47 INFO - 1587209627654 Marionette DEBUG 68 <- [1,2,null,{"value":null}]
[task 2020-04-18T11:33:47.665Z] 11:33:47 INFO - 1587209627660 Marionette DEBUG 68 -> [0,3,"WebDriver:GetTitle",{}]
[task 2020-04-18T11:33:47.665Z] 11:33:47 INFO - 1587209627661 Marionette DEBUG 68 <- [1,3,{"error":"unexpected alert open","message":"Encountered unhandled user prompt dialog","stacktrace":"WebDriverError@chrom ... t@chrome://marionette/content/server.js:249:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20\n"},null]
[task 2020-04-18T11:33:47.665Z] 11:33:47 INFO - 1587209627663 Marionette TRACE Received event DOMModalDialogClosed
[task 2020-04-18T11:33:47.667Z] 11:33:47 INFO - JavaScript error: resource://gre/modul1587209627665 Marionette DEBUG 68 -> [0,4,"WebDriver:GetAlertText",{}]
[task 2020-04-18T11:33:47.667Z] 11:33:47 INFO - es/Prompter.jsm, line 642: NS_ERROR_NOT_AVAILABLE: prompt aborted by user
[task 2020-04-18T11:33:47.667Z] 11:33:47 INFO - 1587209627665 Marionette DEBUG 68 <- [1,4,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:175:5\nNoSuchAle ... t@chrome://marionette/content/server.js:249:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20\n"},null]
[task 2020-04-18T11:33:47.669Z] 11:33:47 INFO - 1587209627667 Marionette DEBUG 68 -> [0,5,"Marionette:GetContext",{}]
[task 2020-04-18T11:33:47.669Z] 11:33:47 INFO - 1587209627667 Marionette DEBUG 68 <- [1,5,null,{"value":"content"}]
[task 2020-04-18T11:33:47.671Z] 11:33:47 INFO - 1587209627669 Marionette DEBUG 68 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-04-18T11:33:47.671Z] 11:33:47 INFO - 1587209627670 Marionette DEBUG 68 <- [1,6,null,{"value":null}]
[task 2020-04-18T11:33:47.673Z] 11:33:47 INFO - 1587209627671 Marionette DEBUG 68 -> [0,7,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2020-04-18T11:33:47.734Z] 11:33:47 INFO - 1587209627727 Marionette DEBUG 68 <- [1,7,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQHCAYAAACjlsT7AAAgAElEQVR4nOzdf4zU933n8f2zuvxxp/ujqvrPWUr/sQhXuZItxVHU448qK ... IQAAAAAMYEIAAAAACMCUAAAAAAGBOAAAAAADAmAAEAAABgTAACAAAAwJgABAAAAIAxAQgAAAAAYwIQAAAAAMYEIAAAAACMBcCER9N+C3CnAAAAAElFTkSuQmCC"}]
[task 2020-04-18T11:33:47.734Z] 11:33:47 INFO - 1587209627729 Marionette DEBUG 68 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2020-04-18T11:33:47.734Z] 11:33:47 INFO - 1587209627729 Marionette DEBUG 68 <- [1,8,null,{"value":null}]
[task 2020-04-18T11:33:47.734Z] 11:33:47 INFO - 1587209627730 Marionette DEBUG 68 -> [0,9,"Marionette:GetContext",{}]
[task 2020-04-18T11:33:47.734Z] 11:33:47 INFO - 1587209627730 Marionette DEBUG 68 <- [1,9,null,{"value":"content"}]
[task 2020-04-18T11:33:47.734Z] 11:33:47 INFO - 1587209627731 Marionette DEBUG 68 -> [0,10,"Marionette:SetContext",{"value":"content"}]
[task 2020-04-18T11:33:47.734Z] 11:33:47 INFO - 1587209627731 Marionette DEBUG 68 <- [1,10,null,{"value":null}]
[task 2020-04-18T11:33:47.734Z] 11:33:47 INFO - 1587209627733 Marionette DEBUG 68 -> [0,11,"WebDriver:GetPageSource",{}]
[task 2020-04-18T11:33:47.736Z] 11:33:47 INFO - 1587209627734 Marionette DEBUG 68 <- [1,11,null,{"value":"<html><head>\n<title>Marionette Test</title>\n</head>\n<body>\n\n \n</body></html>"}]
[task 2020-04-18T11:33:47.738Z] 11:33:47 INFO - 1587209627735 Marionette DEBUG 68 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2020-04-18T11:33:47.738Z] 11:33:47 INFO - 1587209627735 Marionette DEBUG 68 <- [1,12,null,{"value":null}]
[task 2020-04-18T11:33:47.738Z] 11:33:47 ERROR - TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_unhandled_prompt_behavior.py TestUnhandledPromptBehavior.test_ignore_prompt | AssertionError: False != True
[task 2020-04-18T11:33:47.738Z] 11:33:47 INFO - Traceback (most recent call last):
[task 2020-04-18T11:33:47.738Z] 11:33:47 INFO - File "Z:\task_1587209111\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
[task 2020-04-18T11:33:47.738Z] 11:33:47 INFO - testMethod()
[task 2020-04-18T11:33:47.739Z] 11:33:47 INFO - File "Z:\task_1587209111\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 33, in wrapper
[task 2020-04-18T11:33:47.739Z] 11:33:47 INFO - return func(self, *args, **kwargs)
[task 2020-04-18T11:33:47.739Z] 11:33:47 INFO - File "Z:\task_1587209111\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_unhandled_prompt_behavior.py", line 103, in test_ignore
[task 2020-04-18T11:33:47.739Z] 11:33:47 INFO - expected_close=False)
[task 2020-04-18T11:33:47.739Z] 11:33:47 INFO - File "Z:\task_1587209111\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_unhandled_prompt_behavior.py", line 55, in perform_user_prompt_check
[task 2020-04-18T11:33:47.739Z] 11:33:47 INFO - self.assertEqual(self.alert_present, not expected_close)
[task 2020-04-18T11:33:47.739Z] 11:33:47 INFO - TEST-INFO took 112ms
[task 2020-04-18T11:33:47.743Z] 11:33:47 INFO - 1587209627739 Marionette DEBUG 68 -> [0,13,"WebDriver:DismissAlert",{}]
[task 2020-04-18T11:33:47.743Z] 11:33:47 INFO - 1587209627740 Marionette DEBUG 68 <- [1,13,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:175:5\nNoSuchAl ... t@chrome://marionette/content/server.js:249:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20\n"},null]
[task 2020-04-18T11:33:47.743Z] 11:33:47 INFO - 1587209627743 Marionette DEBUG 68 -> [0,14,"WebDriver:DeleteSession",{}]
[task 2020-04-18T11:33:47.748Z] 11:33:47 INFO - 1587209627745 Marionette DEBUG 68 <- [1,14,null,{"value":null}]

The log output is garbled but looks identically to bug 1631112:

[task 2020-04-18T11:33:47.667Z] 11:33:47     INFO -  JavaScript error: resource://gre/modul1587209627665	Marionette	DEBUG	68 -> [0,4,"WebDriver:GetAlertText",{}]
[task 2020-04-18T11:33:47.667Z] 11:33:47     INFO -  es/Prompter.jsm, line 642: NS_ERROR_NOT_AVAILABLE: prompt aborted by user

Means, it's a regression from bug 1615588.

status-firefox76: --- → unaffected
status-firefox77: --- → affected
Flags: needinfo?(pbz)
Regressed by: 1615588
See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=1631112

We track this via bug 1631362 now.

Flags: needinfo?(pbz)
No longer regressed by: 1615588
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_unhandled_prompt_behavior.py TestUnhandledPromptBehavior.test_ignore_prompt | AssertionError: False != True → Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_unhandled_prompt_behavior.py <random> | AssertionError: False != True

No more failures since the patch on bug 1631362 got landed.

Assignee: nobody → pbz
Status: NEW → RESOLVED
Closed: 5 years ago
status-firefox78: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla78
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.