1584868 - Intermittent harness\marionette_harness\tests\unit\test_crash.py TestCrashInTearDown.test_crash_in_teardown | AssertionError: "Process crashed" does not match "Process killed because the connection to Marionette server is lost. Check gecko.log for errors

Status: RESOLVED DUPLICATE of bug 1326124

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

Description

[Treeherder Bug Filer]

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

---

[task 2019-09-29T22:56:38.640Z] 22:56:38 INFO - TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_crash.py TestCrashInTearDown.test_crash_in_teardown
[task 2019-09-29T22:56:38.641Z] 22:56:38 INFO - 1569797798639 Marionette DEBUG Closed connection 2
[task 2019-09-29T22:56:38.644Z] 22:56:38 INFO - 1569797798641 Marionette DEBUG Accepted connection 3 from 127.0.0.1:52531
[task 2019-09-29T22:56:38.644Z] 22:56:38 INFO - 1569797798642 Marionette DEBUG 3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-09-29T22:56:38.644Z] 22:56:38 INFO - 1569797798644 Marionette TRACE [5] Frame script loaded
[task 2019-09-29T22:56:38.651Z] 22:56:38 INFO - 1569797798645 Marionette TRACE [5] Frame script registered
[task 2019-09-29T22:56:38.651Z] 22:56:38 INFO - 1569797798646 Marionette DEBUG 3 <- [1,1,null,{"sessionId":"69081cd9-cc8a-4a7a-9003-19d88d7d5a74","capabilities":{"browserName":"firefox","browserVersion":"71.0a ... p\tmpsvtu_b.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-09-29T22:56:38.651Z] 22:56:38 INFO - 1569797798647 Marionette DEBUG 3 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2019-09-29T22:56:38.651Z] 22:56:38 INFO - 1569797798648 Marionette DEBUG 3 <- [1,2,null,{"value":null}]
[task 2019-09-29T22:56:38.654Z] 22:56:38 INFO - 1569797798649 Marionette DEBUG 3 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2019-09-29T22:56:38.654Z] 22:56:38 INFO - 1569797798650 Marionette DEBUG 3 <- [1,3,null,{"value":null}]
[task 2019-09-29T22:56:38.654Z] 22:56:38 INFO - 1569797798651 Marionette DEBUG 3 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2019-09-29T22:56:38.654Z] 22:56:38 INFO - 1569797798652 Marionette DEBUG 3 <- [1,4,null,{"value":null}]
[task 2019-09-29T22:56:38.654Z] 22:56:38 INFO - 1569797798653 Marionette DEBUG 3 -> [0,5,"Marionette:GetContext",{}]
[task 2019-09-29T22:56:38.654Z] 22:56:38 INFO - 1569797798653 Marionette DEBUG 3 <- [1,5,null,{"value":"content"}]
[task 2019-09-29T22:56:38.661Z] 22:56:38 INFO - 1569797798655 Marionette DEBUG 3 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-09-29T22:56:38.661Z] 22:56:38 INFO - 1569797798655 Marionette DEBUG 3 <- [1,6,null,{"value":null}]
[task 2019-09-29T22:56:38.661Z] 22:56:38 INFO - 1569797798657 Marionette DEBUG 3 -> [0,7,"WebDriver:ExecuteScript",{"script":"Cu.import("resource://gre/modules/AppConstants.jsm");\n return App ... ionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_crash.py","sandbox":"default","line":36}]
[task 2019-09-29T22:56:38.661Z] 22:56:38 INFO - 1569797798659 Marionette DEBUG 3 <- [1,7,null,{"value":true}]
[task 2019-09-29T22:56:38.661Z] 22:56:38 INFO - 1569797798660 Marionette DEBUG 3 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2019-09-29T22:56:38.664Z] 22:56:38 INFO - 1569797798661 Marionette DEBUG 3 <- [1,8,null,{"value":null}]
[task 2019-09-29T22:56:38.667Z] 22:56:38 INFO - 1569797798662 Marionette DEBUG 3 -> [0,9,"Marionette:SetContext",{"value":"content"}]
[task 2019-09-29T22:56:38.667Z] 22:56:38 INFO - 1569797798663 Marionette DEBUG 3 <- [1,9,null,{"value":null}]
[task 2019-09-29T22:56:38.670Z] 22:56:38 INFO - 1569797798666 Marionette DEBUG 3 -> [0,10,"WebDriver:Navigate",{"url":"about:crashparent"}]
[task 2019-09-29T22:56:38.677Z] 22:56:38 INFO - 1569797798674 Marionette TRACE [5] Received DOM event beforeunload for about:blank
[task 2019-09-29T22:56:38.692Z] 22:56:38 INFO - 1569797798682 Marionette TRACE [5] Received DOM event pagehide for about:blank
[task 2019-09-29T22:56:38.692Z] 22:56:38 INFO - 1569797798683 Marionette TRACE [5] Received DOM event unload for about:blank
[task 2019-09-29T22:56:38.692Z] 22:56:38 INFO - 1569797798684 Marionette TRACE [5] Received observer notification outer-window-destroyed
[task 2019-09-29T22:56:38.695Z] 22:56:38 INFO - 1569797798692 Marionette TRACE [24] Frame script loaded
[task 2019-09-29T22:56:38.695Z] 22:56:38 INFO - 1569797798692 Marionette TRACE [24] Frame script registered
[task 2019-09-29T22:57:59.694Z] 22:57:59 INFO - [Child 4372, Chrome_ChildThreExiting due to channel error.
[task 2019-09-29T22:57:59.815Z] 22:57:59 INFO - Application command: Z:\task_1569795114\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\task_1569795114\appdata\local\temp\tmpygifhx.mozrunner
[task 2019-09-29T22:58:00.458Z] 22:58:00 INFO - 1569797880453 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
[task 2019-09-29T22:58:00.458Z] 22:58:00 INFO - 1569797880453 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: telemetry
[task 2019-09-29T22:58:00.458Z] 22:58:00 INFO - 1569797880453 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
[task 2019-09-29T22:58:00.458Z] 22:58:00 INFO - 1569797880453 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
[task 2019-09-29T22:58:00.593Z] 22:58:00 INFO - 1569797880589 Marionette TRACE Received observer notification profile-after-change
[task 2019-09-29T22:58:00.620Z] 22:58:00 INFO - 1569797880615 Marionette TRACE Received observer notification toplevel-window-ready
[task 2019-09-29T22:58:00.655Z] 22:58:00 INFO - 1569797880651 Marionette TRACE Received observer notification command-line-startup
[task 2019-09-29T22:58:00.655Z] 22:58:00 INFO - 1569797880651 Marionette TRACE Received observer notification nsPref:changed
[task 2019-09-29T22:58:00.655Z] 22:58:00 INFO - 1569797880651 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
[task 2019-09-29T22:58:00.790Z] 22:58:00 INFO - 1569797880781 Marionette TRACE Received observer notification toplevel-window-ready
[task 2019-09-29T22:58:02.329Z] 22:58:02 INFO - 1569797882323 Marionette TRACE Received observer notification marionette-startup-requested
[task 2019-09-29T22:58:02.329Z] 22:58:02 INFO - 1569797882324 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2019-09-29T22:58:02.344Z] 22:58:02 INFO - 1569797882335 Marionette TRACE All scripts recorded.
[task 2019-09-29T22:58:02.384Z] 22:58:02 INFO - 1569797882382 Marionette INFO Listening on port 2828
[task 2019-09-29T22:58:02.384Z] 22:58:02 INFO - 1569797882382 Marionette DEBUG Remote service is active
[task 2019-09-29T22:58:02.684Z] 22:58:02 INFO - 1569797882674 Marionette DEBUG Accepted connection 0 from 127.0.0.1:52563
[task 2019-09-29T22:58:02.719Z] 22:58:02 INFO - 1569797882713 Marionette DEBUG Accepted connection 1 from 127.0.0.1:52574
[task 2019-09-29T22:58:02.719Z] 22:58:02 INFO - 1569797882714 Marionette DEBUG Closed connection 1
[task 2019-09-29T22:58:02.719Z] 22:58:02 INFO - 1569797882715 Marionette DEBUG Closed connection 0
[task 2019-09-29T22:58:02.720Z] 22:58:02 INFO - 1569797882716 Marionette DEBUG Accepted connection 2 from 127.0.0.1:52576
[task 2019-09-29T22:58:02.720Z] 22:58:02 INFO - 1569797882717 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-09-29T22:58:02.747Z] 22:58:02 INFO - 1569797882741 Marionette TRACE [20] Frame script loaded
[task 2019-09-29T22:58:02.750Z] 22:58:02 INFO - 1569797882747 Marionette TRACE [20] Frame script registered
[task 2019-09-29T22:58:02.753Z] 22:58:02 INFO - 1569797882750 Marionette DEBUG 2 <- [1,1,null,{"sessionId":"957498e1-404c-483c-9c94-950a08ed18d9","capabilities":{"browserName":"firefox","browserVersion":"71.0a ... p\tmpygifhx.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-09-29T22:58:02.760Z] 22:58:02 INFO - 1569797882754 Marionette DEBUG 2 -> [0,2,"Marionette:GetContext",{}]
[task 2019-09-29T22:58:02.760Z] 22:58:02 INFO - 1569797882754 Marionette DEBUG 2 <- [1,2,null,{"value":"content"}]
[task 2019-09-29T22:58:02.760Z] 22:58:02 INFO - 1569797882755 Marionette DEBUG 2 -> [0,3,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-09-29T22:58:02.760Z] 22:58:02 INFO - 1569797882755 Marionette DEBUG 2 <- [1,3,null,{"value":null}]
[task 2019-09-29T22:58:02.760Z] 22:58:02 INFO - 1569797882757 Marionette DEBUG 2 -> [0,4,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2019-09-29T22:58:02.827Z] 22:58:02 INFO - 1569797882824 Marionette DEBUG 2 <- [1,4,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQHCAYAAACjlsT7AAAgAElEQVR4nOzd65PUB53v8Tw+j/kLeGCVVefBVqmb3VOuTyit2liuG4hkP ... AAAAAYE4AAAAAAMCYAAQAAAGBMAAIAAADAmAAEAAAAgDEBCAAAAABjAhAAAAAAxgQgAAAAAIwJQAAAAAAYE4AAAAAAMBaUW72MjHHIYwAAAABJRU5ErkJggg=="}]
[task 2019-09-29T22:58:02.834Z] 22:58:02 INFO - 1569797882829 Marionette DEBUG 2 -> [0,5,"Marionette:SetContext",{"value":"content"}]
[task 2019-09-29T22:58:02.834Z] 22:58:02 INFO - 1569797882829 Marionette DEBUG 2 <- [1,5,null,{"value":null}]
[task 2019-09-29T22:58:02.834Z] 22:58:02 INFO - 1569797882830 Marionette DEBUG 2 -> [0,6,"Marionette:GetContext",{}]
[task 2019-09-29T22:58:02.834Z] 22:58:02 INFO - 1569797882831 Marionette DEBUG 2 <- [1,6,null,{"value":"content"}]
[task 2019-09-29T22:58:02.834Z] 22:58:02 INFO - 1569797882832 Marionette DEBUG 2 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2019-09-29T22:58:02.834Z] 22:58:02 INFO - 1569797882832 Marionette DEBUG 2 <- [1,7,null,{"value":null}]
[task 2019-09-29T22:58:02.837Z] 22:58:02 INFO - 1569797882834 Marionette DEBUG 2 -> [0,8,"WebDriver:GetPageSource",{}]
[task 2019-09-29T22:58:02.837Z] 22:58:02 INFO - 1569797882836 Marionette DEBUG 2 <- [1,8,null,{"value":"<html><head></head><body></body></html>"}]
[task 2019-09-29T22:58:02.840Z] 22:58:02 ERROR - TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_crash.py TestCrashInTearDown.test_crash_in_teardown | AssertionError: "Process crashed" does not match "Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 10s)"
[task 2019-09-29T22:58:02.840Z] 22:58:02 INFO - Traceback (most recent call last):
[task 2019-09-29T22:58:02.840Z] 22:58:02 INFO - File "Z:\task_1569795114\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 190, in run
[task 2019-09-29T22:58:02.841Z] 22:58:02 INFO - self.tearDown()
[task 2019-09-29T22:58:02.841Z] 22:58:02 INFO - File "Z:\task_1569795114\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_crash.py", line 194, in tearDown
[task 2019-09-29T22:58:02.841Z] 22:58:02 INFO - self.crash, parent=True)
[task 2019-09-29T22:58:02.841Z] 22:58:02 INFO - TEST-INFO took 84200ms

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1584868&startday=2019-09-23&endday=2019-09-29&tree=all

Comment 3

[BMO Automation]

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