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

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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}]

Comment 1

[Intermittent Failures Robot]

1 failures in 4528 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1631204&startday=2020-04-13&endday=2020-04-19&tree=all

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

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.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

We track this via bug 1631362 now.

Comment 4

[Intermittent Failures Robot]

1 failures in 5423 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1631204&startday=2020-04-27&endday=2020-05-03&tree=all

Comment 6

[Intermittent Failures Robot]

3 failures in 5276 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1
• mozilla-central: 1
• autoland: 1

Platform breakdown:

• windows7-32-devedition: 1
• windows7-32-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1631204&startday=2020-05-04&endday=2020-05-10&tree=all

Comment 7

[Intermittent Failures Robot]

2 failures in 5488 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• windows7-32-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1631204&startday=2020-05-11&endday=2020-05-17&tree=all

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+2]]

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

Comment 9

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.