Closed Bug 1461318 Opened 6 years ago Closed 6 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_quit_with_dismissed_beforeunload_prompt | IOError: Process killed after 120s because no connection to Marionette server

Categories

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

Version 3
defect

Tracking

(firefox63 fixed, firefox64 fixed)

RESOLVED FIXED
mozilla64
Tracking Status
firefox63 --- fixed
firefox64 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

NFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_quit_with_dismissed_beforeunload_prompt
[task 2018-05-14T11:59:13.338Z] 11:59:13     INFO -  1526299153323	Marionette	DEBUG	Closed connection 2
[task 2018-05-14T11:59:13.338Z] 11:59:13     INFO -  1526299153326	Marionette	DEBUG	Accepted connection 3 from 127.0.0.1:44046
[task 2018-05-14T11:59:13.339Z] 11:59:13     INFO -  1526299153328	Marionette	TRACE	3 -> [0,1,"WebDriver:NewSession",{}]
[task 2018-05-14T11:59:13.339Z] 11:59:13     INFO -  1526299153335	Marionette	DEBUG	Register listener.js for window 2147483649
[task 2018-05-14T11:59:13.356Z] 11:59:13     INFO -  1526299153349	Marionette	TRACE	3 <- [1,1,null,{"sessionId":"b31f0081-33fa-463f-8fce-bc5384c53eec","capabilities":{"browserName":"firefox","browserVersion":"62.0a ... ssID":5188,"moz:profile":"/tmp/tmptxPEv7.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2018-05-14T11:59:13.356Z] 11:59:13     INFO -  1526299153352	Marionette	TRACE	3 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2018-05-14T11:59:13.359Z] 11:59:13     INFO -  1526299153354	Marionette	TRACE	3 <- [1,2,null,{}]
[task 2018-05-14T11:59:13.360Z] 11:59:13     INFO -  1526299153356	Marionette	TRACE	3 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2018-05-14T11:59:13.363Z] 11:59:13     INFO -  1526299153361	Marionette	TRACE	3 <- [1,3,null,{}]
[task 2018-05-14T11:59:13.366Z] 11:59:13     INFO -  1526299153362	Marionette	TRACE	3 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2018-05-14T11:59:13.367Z] 11:59:13     INFO -  1526299153365	Marionette	TRACE	3 <- [1,4,null,{}]
[task 2018-05-14T11:59:13.371Z] 11:59:13     INFO -  1526299153368	Marionette	TRACE	3 -> [0,5,"Marionette:GetContext",{}]
[task 2018-05-14T11:59:13.372Z] 11:59:13     INFO -  1526299153369	Marionette	TRACE	3 <- [1,5,null,{"value":"content"}]
[task 2018-05-14T11:59:13.375Z] 11:59:13     INFO -  1526299153372	Marionette	TRACE	3 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-05-14T11:59:13.376Z] 11:59:13     INFO -  1526299153373	Marionette	TRACE	3 <- [1,6,null,{}]
[task 2018-05-14T11:59:13.380Z] 11:59:13     INFO -  1526299153376	Marionette	TRACE	3 -> [0,7,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":["startup.homepage_welcome_url",false,"unspecif ... tBranch});\n                return prefs.get(pref, null, Components.interfaces[valueType]);","sandbox":"default","line":879}]
[task 2018-05-14T11:59:13.388Z] 11:59:13     INFO -  1526299153384	Marionette	TRACE	3 <- [1,7,null,{"value":""}]
[task 2018-05-14T11:59:13.389Z] 11:59:13     INFO -  1526299153385	Marionette	TRACE	3 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2018-05-14T11:59:13.394Z] 11:59:13     INFO -  1526299153386	Marionette	TRACE	3 <- [1,8,null,{}]
[task 2018-05-14T11:59:13.394Z] 11:59:13     INFO -  1526299153390	Marionette	TRACE	3 -> [0,9,"Marionette:GetContext",{}]
[task 2018-05-14T11:59:13.395Z] 11:59:13     INFO -  1526299153392	Marionette	TRACE	3 <- [1,9,null,{"value":"content"}]
[task 2018-05-14T11:59:13.403Z] 11:59:13     INFO -  1526299153396	Marionette	TRACE	3 -> [0,10,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-05-14T11:59:13.404Z] 11:59:13     INFO -  1526299153398	Marionette	TRACE	3 <- [1,10,null,{}]
[task 2018-05-14T11:59:13.405Z] 11:59:13     INFO -  1526299153400	Marionette	TRACE	3 -> [0,11,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":["startup.homepage_welcome_url","about:about", ... = new Preferences({defaultBranch: defaultBranch});\n                prefs.set(pref, value);","sandbox":"default","line":913}]
[task 2018-05-14T11:59:13.413Z] 11:59:13     INFO -  1526299153409	Marionette	TRACE	3 <- [1,11,null,{"value":null}]
[task 2018-05-14T11:59:13.414Z] 11:59:13     INFO -  1526299153411	Marionette	TRACE	3 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2018-05-14T11:59:13.416Z] 11:59:13     INFO -  1526299153412	Marionette	TRACE	3 <- [1,12,null,{}]
[task 2018-05-14T11:59:13.418Z] 11:59:13     INFO -  1526299153414	Marionette	TRACE	3 -> [0,13,"WebDriver:Navigate",{"url":"data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cinput%20type%3D%22text%22 ... B%0A%20%20%20%20%20%20%20%20%20%20%20%20%7D%29%3B%0A%20%20%20%20%20%20%20%20%20%20%3C/script%3E%0A%20%20%20%20%20%20%20%20"}]
[task 2018-05-14T11:59:13.438Z] 11:59:13     INFO -  1526299153435	Marionette	DEBUG	Received DOM event beforeunload for about:blank
[task 2018-05-14T11:59:13.459Z] 11:59:13     INFO -  1526299153453	Marionette	DEBUG	Received DOM event pagehide for about:blank
[task 2018-05-14T11:59:13.483Z] 11:59:13     INFO -  1526299153479	Marionette	DEBUG	Received DOM event DOMContentLoaded for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cinput%20type%3D%22text%22%3E%0A%20%20%20%20%20%20%20%20%20%2 ... 9%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%7D%29%3B%0A%20%20%20%20%20%20%20%20%20%20%3C/script%3E%0A%20%20%20%20%20%20%20%20
[task 2018-05-14T11:59:13.653Z] 11:59:13     INFO -  1526299153649	Marionette	DEBUG	Received DOM event pageshow for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cinput%20type%3D%22text%22%3E%0A%20%20%20%20%20%20%20%20%20%2 ... 9%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%7D%29%3B%0A%20%20%20%20%20%20%20%20%20%20%3C/script%3E%0A%20%20%20%20%20%20%20%20
[task 2018-05-14T11:59:13.694Z] 11:59:13     INFO -  1526299153691	Marionette	TRACE	3 <- [1,13,null,{}]
[task 2018-05-14T11:59:13.730Z] 11:59:13     INFO -  1526299153726	Marionette	TRACE	3 -> [0,14,"WebDriver:FindElement",{"using":"tag name","value":"input"}]
[task 2018-05-14T11:59:13.768Z] 11:59:13     INFO -  1526299153757	Marionette	TRACE	3 <- [1,14,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"3822143d-084e-4e96-b3fe-25cf30f15b1f","ELEMENT":"3822143d-084e-4e96-b3fe-25cf30f15b1f"}}]
[task 2018-05-14T11:59:13.768Z] 11:59:13     INFO -  1526299153763	Marionette	TRACE	3 -> [0,15,"WebDriver:ElementSendKeys",{"text":"foo","id":"3822143d-084e-4e96-b3fe-25cf30f15b1f"}]
[task 2018-05-14T11:59:13.814Z] 11:59:13     INFO -  1526299153809	Marionette	TRACE	3 <- [1,15,null,{}]
[task 2018-05-14T11:59:13.815Z] 11:59:13     INFO -  1526299153813	Marionette	TRACE	3 -> [0,16,"Marionette:GetContext",{}]
[task 2018-05-14T11:59:13.819Z] 11:59:13     INFO -  1526299153817	Marionette	TRACE	3 <- [1,16,null,{"value":"content"}]
[task 2018-05-14T11:59:13.828Z] 11:59:13     INFO -  1526299153821	Marionette	TRACE	3 -> [0,17,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-05-14T11:59:13.828Z] 11:59:13     INFO -  1526299153822	Marionette	TRACE	3 <- [1,17,null,{}]
[task 2018-05-14T11:59:13.829Z] 11:59:13     INFO -  1526299153826	Marionette	TRACE	3 -> [0,18,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"../../venv/lib/python2.7/site-p ... ancelQuit, \"quit-application-requested\", null);\n                return cancelQuit.data;","sandbox":"default","line":1048}]
[task 2018-05-14T11:59:13.869Z] 11:59:13     INFO -  1526299153864	Marionette	TRACE	3 <- [1,18,null,{"value":false}]
[task 2018-05-14T11:59:13.906Z] 11:59:13     INFO -  1526299153899	Marionette	TRACE	3 -> [0,19,"Marionette:SetContext",{"value":"content"}]
[task 2018-05-14T11:59:13.906Z] 11:59:13     INFO -  1526299153901	Marionette	TRACE	3 <- [1,19,null,{}]
[task 2018-05-14T11:59:13.907Z] 11:59:13     INFO -  1526299153904	Marionette	TRACE	3 -> [0,20,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2018-05-14T11:59:13.911Z] 11:59:13     INFO -  1526299153908	Marionette	DEBUG	New connections will no longer be accepted
[task 2018-05-14T11:59:14.089Z] 11:59:14     INFO -  1526299154083	Marionette	TRACE	3 <- [1,20,null,{"cause":"shutdown"}]
[task 2018-05-14T11:59:14.166Z] 11:59:14     INFO -  1526299154157	Marionette	DEBUG	Closed connection 3
[task 2018-05-14T11:59:14.663Z] 11:59:14     INFO -  *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping
[task 2018-05-14T11:59:14.845Z] 11:59:14     INFO -  1526299154840	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-05-14T11:59:16.115Z] 11:59:16     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmptxPEv7.mozrunner
[task 2018-05-14T12:01:16.230Z] 12:01:16     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_quit_with_dismissed_beforeunload_prompt | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors
[task 2018-05-14T12:01:16.231Z] 12:01:16     INFO - Traceback (most recent call last):
[task 2018-05-14T12:01:16.232Z] 12:01:16     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2018-05-14T12:01:16.233Z] 12:01:16     INFO -     testMethod()
[task 2018-05-14T12:01:16.234Z] 12:01:16     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py", line 307, in test_in_app_quit_with_dismissed_beforeunload_prompt
[task 2018-05-14T12:01:16.236Z] 12:01:16     INFO -     self.marionette.start_session()
[task 2018-05-14T12:01:16.237Z] 12:01:16     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2018-05-14T12:01:16.238Z] 12:01:16     INFO -     return func(*args, **kwargs)
[task 2018-05-14T12:01:16.240Z] 12:01:16     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1211, in start_session
[task 2018-05-14T12:01:16.241Z] 12:01:16     INFO -     self.start_binary(timeout)
[task 2018-05-14T12:01:16.242Z] 12:01:16     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 640, in start_binary
[task 2018-05-14T12:01:16.243Z] 12:01:16     INFO -     reraise(IOError, msg.format(timeout), tb)
[task 2018-05-14T12:01:16.244Z] 12:01:16     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 631, in start_binary
[task 2018-05-14T12:01:16.245Z] 12:01:16     INFO -     self.raise_for_port(timeout=timeout)
[task 2018-05-14T12:01:16.246Z] 12:01:16     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 711, in raise_for_port
[task 2018-05-14T12:01:16.247Z] 12:01:16     INFO -     self.host, self.port))
[task 2018-05-14T12:01:16.249Z] 12:01:16     INFO - TEST-INFO took 122911ms
[task 2018-05-14T12:01:16.250Z] 12:01:16     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmpuQlE68.mozrunner
[task 2018-05-14T12:01:18.439Z] 12:01:18     INFO -  1526299278437	Marionette	DEBUG	Received observer notification profile-after-change
[task 2018-05-14T12:01:18.597Z] 12:01:18     INFO -  1526299278590	Marionette	DEBUG	Received observer notification command-line-startup
[task 2018-05-14T12:01:18.597Z] 12:01:18     INFO -  1526299278591	Marionette	DEBUG	Received observer notification nsPref:changed
[task 2018-05-14T12:01:22.099Z] 12:01:22     INFO -  1526299282097	Marionette	DEBUG	Received observer notification sessionstore-windows-restored
[task 2018-05-14T12:01:24.539Z] 12:01:24     INFO -  1526299284532	Marionette	DEBUG	New connections are accepted
[task 2018-05-14T12:01:24.540Z] 12:01:24     INFO -  1526299284534	Marionette	INFO	Listening on port 2828
[task 2018-05-14T12:01:24.650Z] 12:01:24     INFO -  1526299284643	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:46674
[task 2018-05-14T12:01:24.658Z] 12:01:24     INFO -  1526299284652	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:46676
[task 2018-05-14T12:01:24.659Z] 12:01:24     INFO -  1526299284654	Marionette	DEBUG	Closed connection 0
[task 2018-05-14T12:01:24.664Z] 12:01:24     INFO -  1526299284658	Marionette	TRACE	1 -> [0,1,"WebDriver:NewSession",{}]
[task 2018-05-14T12:01:24.826Z] 12:01:24     INFO -  1526299284820	Marionette	DEBUG	Register listener.js for window 2147483649
[task 2018-05-14T12:01:24.903Z] 12:01:24     INFO -  1526299284894	Marionette	TRACE	1 <- [1,1,null,{"sessionId":"f7ea954b-81cf-4bde-be5d-59b3558c3c9e","capabilities":{"browserName":"firefox","browserVersion":"62.0a ... ssID":5340,"moz:profile":"/tmp/tmpuQlE68.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2018-05-14T12:01:24.920Z] 12:01:24     INFO -  1526299284913	Marionette	TRACE	1 -> [0,2,"Marionette:GetContext",{}]
[task 2018-05-14T12:01:24.920Z] 12:01:24     INFO -  1526299284915	Marionette	TRACE	1 <- [1,2,null,{"value":"content"}]
[task 2018-05-14T12:01:24.922Z] 12:01:24     INFO -  1526299284918	Marionette	TRACE	1 -> [0,3,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-05-14T12:01:24.925Z] 12:01:24     INFO -  1526299284919	Marionette	TRACE	1 <- [1,3,null,{}]
[task 2018-05-14T12:01:24.954Z] 12:01:24     INFO -  1526299284951	Marionette	TRACE	1 -> [0,4,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":["startup.homepage_welcome_url"],"filename":".. ... resource://gre/modules/Preferences.jsm\");\n               Preferences.reset(arguments[0]);","sandbox":"default","line":851}]
[task 2018-05-14T12:01:24.970Z] 12:01:24     INFO -  1526299284961	Marionette	TRACE	1 <- [1,4,null,{"value":null}]
[task 2018-05-14T12:01:24.971Z] 12:01:24     INFO -  1526299284964	Marionette	TRACE	1 -> [0,5,"Marionette:SetContext",{"value":"content"}]
[task 2018-05-14T12:01:24.973Z] 12:01:24     INFO -  1526299284966	Marionette	TRACE	1 <- [1,5,null,{}]
[task 2018-05-14T12:01:24.977Z] 12:01:24     INFO -  1526299284975	Marionette	TRACE	1 -> [0,6,"WebDriver:DeleteSession",{}]
Depends on a fix for bug 1433873.
Depends on: 1433873
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=193021641&repo=mozilla-inbound&lineNumber=34674
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
All recent failures are happening due to start-up hangs of Linux64 ASAN builds. A fix is needed on bug 1487243.
Depends on: 1487243
This failure should be fixed now with the patch on bug 1495404 for both central and beta.
Assignee: nobody → stransky
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
No longer depends on: 1433873
Resolution: --- → FIXED
Target Milestone: --- → mozilla64
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.