1539313 - windows/aarch64 - testing\marionette\harness\marionette_harness\tests\unit\test_crash.py TestCrash.test_crash_content_process | AssertionError: "Content process crashed" does not match "Process has been unexpectedly closed (Exit code: 0)

Status: RESOLVED DUPLICATE of bug 1539312

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: egao [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=236167486&repo=try

https://queue.taskcluster.net/v1/task/ezptD6kvQCS8yIzs8JVJrw/runs/0/artifacts/public/logs/live_backing.log

Test: Mn

Platform: windows10-aarch64

Context:
21:28:13 INFO - TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_crash.py TestCrash.test_crash_content_process
21:28:13 INFO - 1553635693372 Marionette DEBUG Closed connection 3
21:28:13 INFO - 1553635693375 Marionette DEBUG Accepted connection 4 from 127.0.0.1:52753
21:28:13 INFO - 1553635693378 Marionette DEBUG 4 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
21:28:13 INFO - 1553635693381 Marionette TRACE [2147483649] Frame script loaded
21:28:13 INFO - 1553635693383 Marionette TRACE [2147483649] Frame script registered
21:28:13 INFO - 1553635693386 Marionette DEBUG 4 <- [1,1,null,{"sessionId":"f5f7edfc-82cf-4015-bc1f-6037ba4f9f1f","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... p\\tmpjq3pvd.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
21:28:13 INFO - 1553635693390 Marionette DEBUG 4 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
21:28:13 INFO - 1553635693391 Marionette DEBUG 4 <- [1,2,null,{"value":null}]
21:28:13 INFO - 1553635693393 Marionette DEBUG 4 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
21:28:13 INFO - 1553635693394 Marionette DEBUG 4 <- [1,3,null,{"value":null}]
21:28:13 INFO - 1553635693396 Marionette DEBUG 4 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
21:28:13 INFO - 1553635693397 Marionette DEBUG 4 <- [1,4,null,{"value":null}]
21:28:13 INFO - 1553635693401 Marionette DEBUG 4 -> [0,5,"Marionette:GetContext",{}]
21:28:13 INFO - 1553635693401 Marionette DEBUG 4 <- [1,5,null,{"value":"content"}]
21:28:13 INFO - 1553635693404 Marionette DEBUG 4 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
21:28:13 INFO - 1553635693404 Marionette DEBUG 4 <- [1,6,null,{"value":null}]
21:28:13 INFO - 1553635693408 Marionette DEBUG 4 -> [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":34}]
21:28:13 INFO - 1553635693411 Marionette DEBUG 4 <- [1,7,null,{"value":true}]
21:28:13 INFO - 1553635693413 Marionette DEBUG 4 -> [0,8,"Marionette:SetContext",{"value":"content"}]
21:28:13 INFO - 1553635693414 Marionette DEBUG 4 <- [1,8,null,{"value":null}]
21:28:13 INFO - 1553635693418 Marionette DEBUG 4 -> [0,9,"Marionette:GetContext",{}]
21:28:13 INFO - 1553635693420 Marionette DEBUG 4 <- [1,9,null,{"value":"content"}]
21:28:13 INFO - 1553635693422 Marionette DEBUG 4 -> [0,10,"Marionette:SetContext",{"value":"chrome"}]
21:28:13 INFO - 1553635693422 Marionette DEBUG 4 <- [1,10,null,{"value":null}]
21:28:13 INFO - 1553635693426 Marionette DEBUG 4 -> [0,11,"WebDriver:ExecuteScript",{"script":"try {\n return Services.appinfo.browserTabsRemoteAutostart;\n ... 3634905\\build\\venv\\lib\\site-packages\\marionette_harness\\marionette_test\\decorators.py","sandbox":"default","line":66}]
21:28:13 INFO - 1553635693429 Marionette DEBUG 4 <- [1,11,null,{"value":true}]
21:28:13 INFO - 1553635693431 Marionette DEBUG 4 -> [0,12,"Marionette:SetContext",{"value":"content"}]
21:28:13 INFO - 1553635693432 Marionette DEBUG 4 <- [1,12,null,{"value":null}]
21:28:13 INFO - 1553635693436 Marionette DEBUG 4 -> [0,13,"Marionette:SetContext",{"value":"content"}]
21:28:13 INFO - 1553635693437 Marionette DEBUG 4 <- [1,13,null,{"value":null}]
21:28:13 INFO - 1553635693438 Marionette DEBUG 4 -> [0,14,"WebDriver:Navigate",{"url":"about:crashcontent"}]
21:28:13 INFO - 1553635693448 Marionette TRACE [2147483649] Received DOM event beforeunload for about:blank
21:28:13 INFO - ###!!! [Parent][MessageChannel] Error: (msgtype=0x1F0099,name=PBrowser::Msg_UpdateNativeWindowHandle) Channel error: cannot send/recv
21:28:13 INFO - ###!!! [Parent][MessageChannel] Error: (msgtype=0x1F0088,name=PBrowser::Msg_Destroy) Channel error: cannot send/recv
21:28:13 INFO - 1553635693521 Marionette TRACE [12] Frame script loaded
21:28:13 INFO - 1553635693522 Marionette TRACE [12] Frame script registered
21:28:13 INFO - A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
21:28:13 INFO - ###!!! [Parent][MessageChannel] Error: (msgtype=0x36003E,name=PContent::Msg_NotifyProcessPriorityChanged) Channel error: cannot send/recv
21:28:13 INFO - 1553635693605 Marionette TRACE [12] Check readyState uninitialized for about:blank
21:28:13 INFO - [Parent 2732, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
21:28:13 INFO - 1553635693684 Marionette TRACE Received DOM event unload for [object XULDocument]
21:28:13 INFO - 1553635693704 Marionette TRACE Received observer notification message-manager-disconnect
21:28:13 INFO - 1553635693709 Marionette DEBUG 4 <- [1,14,null,{"value":null}]
21:28:13 INFO - [Parent 2732, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 160
21:28:13 INFO - [Child 9108, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
21:28:13 INFO - [Child 9108, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
21:28:13 INFO - 1553635693722 Marionette DEBUG 4 -> [0,15,"WebDriver:GetCurrentURL",{}]
21:28:13 INFO - 1553635693723 Marionette DEBUG 4 <- [1,15,{"error":"no such window","message":"Browsing context has been discarded","stacktrace":"WebDriverError@chrome://marione ... t@chrome://marionette/content/server.js:236:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:492:20\n"},null]
21:28:13 INFO - 1553635693731 Marionette DEBUG Closed connection 4
21:28:13 INFO - [Parent 2732, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
21:28:13 INFO - [Child 1980, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
21:28:14 INFO - [Child 1980, Chrome_1553635694017 Marionette TRACE Received observer notification xpcom-will-shutdown
21:28:14 INFO - 1553635694018 Marionette INFO Stopped listening on port 2828
21:28:14 INFO - 1553635694018 Marionette DEBUG Remote service is inactive
21:28:14 INFO - [GPU 8304, Chrome_ChildThread] WARNI
21:28:14 INFO - ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
21:28:14 INFO - NG: pipe error: 109: file z:/build/build/sr
21:28:14 INFO - ###!!! [Child][MessageChannel::SendAndWait] Error: Channel error: cannot send/recv
21:28:19 ERROR - TEST-UNEXPECTED-FAIL | testing\marionette\harness\marionette_harness\tests\unit\test_crash.py TestCrash.test_crash_content_process | AssertionError: "Content process crashed" does not match "Process has been unexpectedly closed (Exit code: 0) (Reason: [Errno 10053] An established connection was aborted by the software in your host machine)"
21:28:19 INFO - Traceback (most recent call last):
21:28:19 INFO - File "C:\tasks\task_1553634905\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
21:28:19 INFO - testMethod()
21:28:19 INFO - File "C:\tasks\task_1553634905\build\venv\lib\site-packages\marionette_harness\marionette_test\decorators.py", line 69, in skip_wrapper
21:28:19 INFO - return test_item(self, *args, **kwargs)
21:28:19 INFO - File "C:\tasks\task_1553634905\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_crash.py", line 128, in test_crash_content_process
21:28:19 INFO - message="Expected IOError exception for content crash not raised."
21:28:19 INFO - TEST-INFO took 6223ms
21:28:19 INFO - Application command: C:\tasks\task_1553634905\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\testdr~1\appdata\local\temp\tmpjq3pvd.mozrunner
21:28:19 INFO - 1553635699892 Marionette TRACE Received observer notification profile-after-change
21:28:19 INFO - 1553635699945 Marionette TRACE Received observer notification command-line-startup
21:28:19 INFO - 1553635699945 Marionette TRACE Received observer notification nsPref:changed
21:28:19 INFO - 1553635699945 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
21:28:19 INFO - 1553635699985 Marionette TRACE Received observer notification toplevel-window-ready
21:28:21 INFO - 1553635701205 Marionette TRACE Received observer notification marionette-startup-requested
21:28:21 INFO - 1553635701205 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
21:28:21 INFO - 1553635701235 Marionette TRACE All scripts recorded.
21:28:21 INFO - 1553635701262 Marionette INFO Listening on port 2828
21:28:21 INFO - 1553635701262 Marionette DEBUG Remote service is active
21:28:21 INFO - 1553635701337 Marionette DEBUG Accepted connection 0 from 127.0.0.1:52763
21:28:21 INFO - 1553635701428 Marionette DEBUG Accepted connection 1 from 127.0.0.1:52772
21:28:21 INFO - 1553635701430 Marionette DEBUG Closed connection 1
21:28:21 INFO - 1553635701431 Marionette DEBUG Closed connection 0
21:28:21 INFO - 1553635701431 Marionette DEBUG Accepted connection 2 from 127.0.0.1:52773
21:28:21 INFO - 1553635701434 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
21:28:21 INFO - 1553635701465 Marionette TRACE [2147483649] Frame script loaded
21:28:21 INFO - 1553635701471 Marionette TRACE [2147483649] Frame script registered
21:28:21 INFO - 1553635701478 Marionette DEBUG 2 <- [1,1,null,{"sessionId":"9c42cc79-7536-4427-9436-1bfa1b52b355","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... p\\tmpjq3pvd.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
21:28:21 INFO - 1553635701502 Marionette DEBUG 2 -> [0,2,"WebDriver:DeleteSession",{}]
21:28:21 INFO - 1553635701504 Marionette DEBUG 2 <- [1,2,null,{"value":null}]

Comment 1

[Edwin Takahashi (:egao | infrequent contributor)]

Closing this bug instead of making separate bugs, since the root cause appears to be the same.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• windows10-aarch64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1539313&startday=2019-03-25&endday=2019-03-31&tree=all