Closed Bug 1597717 Opened 6 years ago Closed 6 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason:

Categories

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

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

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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

[task 2019-11-19T13:28:56.528Z] 13:28:56 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation
[task 2019-11-19T13:28:56.528Z] 13:28:56 INFO - 1574170136505 Marionette DEBUG 511 -> [0,28,"WebDriver:GetWindowHandles",{}]
[task 2019-11-19T13:28:56.529Z] 13:28:56 INFO - 1574170136505 Marionette DEBUG 511 <- [1,28,null,["41"]]
[task 2019-11-19T13:28:56.529Z] 13:28:56 INFO - 1574170136506 Marionette DEBUG 511 -> [0,29,"WebDriver:DeleteSession",{}]
[task 2019-11-19T13:28:56.529Z] 13:28:56 INFO - 1574170136507 Marionette DEBUG 511 <- [1,29,null,{"value":null}]
[task 2019-11-19T13:28:56.529Z] 13:28:56 INFO - 1574170136509 Marionette DEBUG Closed connection 511
[task 2019-11-19T13:28:56.529Z] 13:28:56 INFO - 1574170136510 Marionette DEBUG Accepted connection 512 from 127.0.0.1:50938
[task 2019-11-19T13:28:56.529Z] 13:28:56 INFO - 1574170136510 Marionette DEBUG 512 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-11-19T13:28:56.529Z] 13:28:56 INFO - 1574170136511 Marionette TRACE [41] Frame script loaded
[task 2019-11-19T13:28:56.529Z] 13:28:56 INFO - 1574170136512 Marionette TRACE [41] Frame script registered
[task 2019-11-19T13:28:56.529Z] 13:28:56 INFO - 1574170136513 Marionette DEBUG 512 <- [1,1,null,{"sessionId":"72ad5717-29b4-c74d-8272-f3ff73f81a90","capabilities":{"browserName":"firefox","browserVersion":"72.0" ... /T/tmpJ7SP1b.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-11-19T13:28:56.530Z] 13:28:56 INFO - 1574170136514 Marionette DEBUG 512 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2019-11-19T13:28:56.530Z] 13:28:56 INFO - 1574170136514 Marionette DEBUG 512 <- [1,2,null,{"value":null}]
[task 2019-11-19T13:28:56.530Z] 13:28:56 INFO - 1574170136515 Marionette DEBUG 512 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2019-11-19T13:28:56.530Z] 13:28:56 INFO - 1574170136515 Marionette DEBUG 512 <- [1,3,null,{"value":null}]
[task 2019-11-19T13:28:56.530Z] 13:28:56 INFO - 1574170136516 Marionette DEBUG 512 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2019-11-19T13:28:56.530Z] 13:28:56 INFO - 1574170136516 Marionette DEBUG 512 <- [1,4,null,{"value":null}]
[task 2019-11-19T13:28:56.530Z] 13:28:56 INFO - 1574170136516 Marionette DEBUG 512 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2019-11-19T13:28:56.530Z] 13:28:56 INFO - 1574170136517 Marionette DEBUG 512 <- [1,5,null,{"value":"3"}]
[task 2019-11-19T13:28:56.530Z] 13:28:56 INFO - 1574170136517 Marionette DEBUG 512 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2019-11-19T13:28:56.531Z] 13:28:56 INFO - 1574170136517 Marionette DEBUG 512 <- [1,6,null,["3"]]
[task 2019-11-19T13:28:56.531Z] 13:28:56 INFO - 1574170136518 Marionette DEBUG 512 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2019-11-19T13:28:56.531Z] 13:28:56 INFO - 1574170136519 Marionette DEBUG 512 <- [1,7,null,{"value":"41"}]
[task 2019-11-19T13:28:56.531Z] 13:28:56 INFO - 1574170136519 Marionette DEBUG 512 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2019-11-19T13:28:56.531Z] 13:28:56 INFO - 1574170136519 Marionette DEBUG 512 <- [1,8,null,["41"]]
[task 2019-11-19T13:28:56.531Z] 13:28:56 INFO - 1574170136521 Marionette DEBUG 512 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2019-11-19T13:28:56.531Z] 13:28:56 INFO - 1574170136521 Marionette DEBUG 512 <- [1,9,null,["41"]]
[task 2019-11-19T13:28:56.531Z] 13:28:56 INFO - 1574170136522 Marionette DEBUG 512 -> [0,10,"WebDriver:NewWindow",{"type":"tab","focus":false}]
[task 2019-11-19T13:28:56.532Z] 13:28:56 INFO - 1574170136526 Marionette TRACE Received DOM event TabOpen for [object XULElement]
[task 2019-11-19T13:28:56.582Z] 13:28:56 INFO - 1574170136574 Marionette TRACE [255] Frame script loaded
[task 2019-11-19T13:28:56.582Z] 13:28:56 INFO - 1574170136575 Marionette TRACE [255] Frame script registered
[task 2019-11-19T13:28:56.622Z] 13:28:56 INFO - 1574170136593 Marionette DEBUG 512 <- [1,10,null,{"handle":"255","type":"tab"}]
[task 2019-11-19T13:28:56.622Z] 13:28:56 INFO - 1574170136595 Marionette DEBUG 512 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2019-11-19T13:28:56.622Z] 13:28:56 INFO - 1574170136595 Marionette DEBUG 512 <- [1,11,null,["41","255"]]
[task 2019-11-19T13:28:56.622Z] 13:28:56 INFO - 1574170136596 Marionette DEBUG 512 -> [0,12,"WebDriver:GetWindowHandles",{}]
[task 2019-11-19T13:28:56.622Z] 13:28:56 INFO - 1574170136596 Marionette DEBUG 512 <- [1,12,null,["41","255"]]
[task 2019-11-19T13:28:56.622Z] 13:28:56 INFO - 1574170136599 Marionette DEBUG 512 -> [0,13,"WebDriver:SwitchToWindow",{"handle":"255","focus":true,"name":"255"}]
[task 2019-11-19T13:28:56.637Z] 13:28:56 INFO - 1574170136619 Marionette TRACE Received DOM event TabSelect for [object XULElement]
[task 2019-11-19T13:28:56.668Z] 13:28:56 INFO - 1574170136658 Marionette DEBUG 512 <- [1,13,null,{"value":null}]
[task 2019-11-19T13:28:56.668Z] 13:28:56 INFO - 1574170136665 Marionette DEBUG 512 -> [0,14,"WebDriver:GetTimeouts",{}]
[task 2019-11-19T13:28:56.668Z] 13:28:56 INFO - 1574170136665 Marionette DEBUG 512 <- [1,14,null,{"implicit":0,"pageLoad":300000,"script":30000}]
[task 2019-11-19T13:28:56.690Z] 13:28:56 INFO - 1574170136685 Marionette DEBUG 512 -> [0,15,"WebDriver:ExecuteScript",{"script":"return window.history.length;","newSandbox":true,"args":[],"filename":"tests/testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py","sandbox":"default","line":74}]
[task 2019-11-19T13:28:56.769Z] 13:28:56 INFO - 1574170136694 Marionette DEBUG 512 <- [1,15,null,{"value":1}]
[task 2019-11-19T13:28:56.769Z] 13:28:56 INFO - 1574170136695 Marionette DEBUG 512 -> [0,16,"Marionette:GetContext",{}]
[task 2019-11-19T13:28:56.769Z] 13:28:56 INFO - 1574170136695 Marionette DEBUG 512 <- [1,16,null,{"value":"content"}]
[task 2019-11-19T13:28:56.769Z] 13:28:56 INFO - 1574170136696 Marionette DEBUG 512 -> [0,17,"WebDriver:DeleteSession",{}]
[task 2019-11-19T13:28:56.770Z] 13:28:56 INFO - 1574170136716 Marionette DEBUG 512 <- [1,17,null,{"value":null}]
[task 2019-11-19T13:28:56.868Z] 13:28:56 INFO - Application command: /Users/cltbld/tasks/task_1574169950/build/application/Firefox Developer Edition.app/Contents/MacOS/firefox -no-remote -marionette -foreground -profile /var/folders/lt/fckkj5j942sbs3_d_tgtl6gr000017/T/tmpJ7SP1b.mozrunner
[task 2019-11-19T13:28:57.126Z] 13:28:57 INFO - JavaScript error: resource://gre/modules/AddonManager.jsm, line 4822: uncaught exception: out of memory
[task 2019-11-19T13:28:57.153Z] 13:28:57 INFO - 1574170137140 Marionette TRACE Received observer notification profile-after-change
[task 2019-11-19T13:28:57.293Z] 13:28:57 INFO - 1574170137276 Marionette TRACE Received observer notification command-line-startup
[task 2019-11-19T13:29:16.791Z] 13:29:16 INFO - JavaScript error: resource:///modules/BrowserGlue.jsm, line 1246: uncaught exception: out of memory
[task 2019-11-19T13:29:36.950Z] 13:29:36 INFO - 1574170176928 Marionette TRACE Received observer notification toplevel-window-ready
[task 2019-11-19T13:29:56.482Z] 13:29:56 INFO - JavaScript error: resource://gre/modules/UpdateTimerManager.jsm, line 219: uncaught exception: out of memory
[task 2019-11-19T13:31:11.803Z] 13:31:11 INFO - 2019-11-19 13:31:11.700 firefox[1562:9855] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.firefoxdeveloperedition.savedState/window_1.data: No such file or directory (2)
[task 2019-11-19T13:31:13.099Z] 13:31:13 INFO - 1574170273066 Marionette TRACE Received observer notification marionette-startup-requested
[task 2019-11-19T13:31:13.099Z] 13:31:13 INFO - 1574170273067 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2019-11-19T13:31:13.127Z] 13:31:13 INFO - 1574170273116 Marionette TRACE All scripts recorded.
[task 2019-11-19T13:31:13.210Z] 13:31:13 INFO - 1574170273205 Marionette INFO Listening on port 2828
[task 2019-11-19T13:31:13.210Z] 13:31:13 INFO - 1574170273206 Marionette DEBUG Remote service is active
[task 2019-11-19T13:32:11.576Z] 13:32:11 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on 127.0.0.1:2828!)
[task 2019-11-19T13:32:11.576Z] 13:32:11 INFO - Traceback (most recent call last):
[task 2019-11-19T13:32:11.577Z] 13:32:11 INFO - File "/Users/cltbld/tasks/task_1574169950/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2019-11-19T13:32:11.577Z] 13:32:11 INFO - testMethod()
[task 2019-11-19T13:32:11.577Z] 13:32:11 INFO - File "/Users/cltbld/tasks/task_1574169950/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/decorators.py", line 84, in skip_wrapper
[task 2019-11-19T13:32:11.577Z] 13:32:11 INFO - return test_item(self, *args, **kwargs)
[task 2019-11-19T13:32:11.577Z] 13:32:11 INFO - File "/Users/cltbld/tasks/task_1574169950/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py", line 285, in test_focus_after_navigation
[task 2019-11-19T13:32:11.577Z] 13:32:11 INFO - self.marionette.restart()
[task 2019-11-19T13:32:11.577Z] 13:32:11 INFO - File "/Users/cltbld/tasks/task_1574169950/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
[task 2019-11-19T13:32:11.577Z] 13:32:11 INFO - m._handle_socket_failure()
[task 2019-11-19T13:32:11.577Z] 13:32:11 INFO - File "/Users/cltbld/tasks/task_1574169950/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 678, in _handle_socket_failure
[task 2019-11-19T13:32:11.577Z] 13:32:11 INFO - reraise(IOError, message.format(returncode=returncode, reason=val), tb)
[task 2019-11-19T13:32:11.578Z] 13:32:11 INFO - File "/Users/cltbld/tasks/task_1574169950/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2019-11-19T13:32:11.578Z] 13:32:11 INFO - return func(*args, **kwargs)
[task 2019-11-19T13:32:11.578Z] 13:32:11 INFO - File "/Users/cltbld/tasks/task_1574169950/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1052, in restart
[task 2019-11-19T13:32:11.578Z] 13:32:11 INFO - self.raise_for_port(timeout=self.DEFAULT_STARTUP_TIMEOUT)
[task 2019-11-19T13:32:11.578Z] 13:32:11 INFO - File "/Users/cltbld/tasks/task_1574169950/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 569, in raise_for_port
[task 2019-11-19T13:32:11.578Z] 13:32:11 INFO - self.host, self.port))

After the restart there seems to be an OOM situation:

[task 2019-11-19T13:28:57.126Z] 13:28:57     INFO -  JavaScript error: resource://gre/modules/AddonManager.jsm, line 4822: uncaught exception: out of memory
[task 2019-11-19T13:28:57.153Z] 13:28:57     INFO -  1574170137140	Marionette	TRACE	Received observer notification profile-after-change
[task 2019-11-19T13:28:57.293Z] 13:28:57     INFO -  1574170137276	Marionette	TRACE	Received observer notification command-line-startup
[task 2019-11-19T13:29:16.791Z] 13:29:16     INFO -  JavaScript error: resource:///modules/BrowserGlue.jsm, line 1246: uncaught exception: out of memory
[task 2019-11-19T13:29:36.950Z] 13:29:36     INFO -  1574170176928	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2019-11-19T13:29:56.482Z] 13:29:56     INFO -  JavaScript error: resource://gre/modules/UpdateTimerManager.jsm, line 219: uncaught exception: out of memory

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
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.