Closed Bug 1469820 Opened 6 years ago Closed 6 years ago

Intermittent test_quit_restart.py TestQuitRestart.test_keep_context_after_restart_by_using_context, TestQuitRestart.test_reset_context_after_quit_by_using_context | MarionetteException: Please start a session

Categories

(Testing :: Firefox UI Tests, defect, P5)

Version 3
defect

Tracking

(firefox64 fixed)

RESOLVED FIXED
mozilla64
Tracking Status
firefox64 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Filed by: apavel [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=183947728&repo=autoland

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

[task 2018-06-20T10:13:12.497Z] 10:13:12     INFO -  1529489592492	Marionette	TRACE	2 -> [0,19,"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":1047}]
[task 2018-06-20T10:13:12.517Z] 10:13:12     INFO -  1529489592514	Marionette	TRACE	2 <- [1,19,null,{"value":false}]
[task 2018-06-20T10:13:12.534Z] 10:13:12     INFO -  1529489592523	Marionette	TRACE	2 -> [0,20,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-06-20T10:13:12.535Z] 10:13:12     INFO -  1529489592525	Marionette	TRACE	2 <- [1,20,null,{"value":null}]
[task 2018-06-20T10:13:12.535Z] 10:13:12     INFO -  1529489592529	Marionette	TRACE	2 -> [0,21,"Marionette:Quit",{"flags":["eForceQuit","eRestart"]}]
[task 2018-06-20T10:13:12.537Z] 10:13:12     INFO -  1529489592531	Marionette	INFO	Stopped listening on port 2828
[task 2018-06-20T10:13:12.683Z] 10:13:12     INFO -  1529489592678	Marionette	TRACE	2 <- [1,21,null,{"cause":"restart"}]
[task 2018-06-20T10:13:12.784Z] 10:13:12     INFO -  1529489592781	Marionette	DEBUG	Closed connection 2
[task 2018-06-20T10:13:13.386Z] 10:13:13     INFO -  1529489593382	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-06-20T10:13:13.388Z] 10:13:13     INFO -  1529489593383	Marionette	DEBUG	Remote service is inactive
[task 2018-06-20T10:19:13.915Z] 10:19:13     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_keep_context_after_restart_by_using_context | MarionetteException: Please start a session
[task 2018-06-20T10:19:13.915Z] 10:19:13     INFO - Traceback (most recent call last):
[task 2018-06-20T10:19:13.918Z] 10:19:13     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2018-06-20T10:19:13.919Z] 10:19:13     INFO -     testMethod()
[task 2018-06-20T10:19:13.921Z] 10:19:13     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py", line 359, in test_keep_context_after_restart_by_using_context
[task 2018-06-20T10:19:13.922Z] 10:19:13     INFO -     "Not in chrome context after a restart with using_context")
[task 2018-06-20T10:19:13.923Z] 10:19:13     INFO -   File "/usr/lib/python2.7/contextlib.py", line 35, in __exit__
[task 2018-06-20T10:19:13.924Z] 10:19:13     INFO -     self.gen.throw(type, value, traceback)
[task 2018-06-20T10:19:13.925Z] 10:19:13     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1437, in using_context
[task 2018-06-20T10:19:13.927Z] 10:19:13     INFO -     self.set_context(scope)
[task 2018-06-20T10:19:13.928Z] 10:19:13     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1414, in set_context
[task 2018-06-20T10:19:13.929Z] 10:19:13     INFO -     {"value": context})
[task 2018-06-20T10:19:13.931Z] 10:19:13     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2018-06-20T10:19:13.932Z] 10:19:13     INFO -     return func(*args, **kwargs)
[task 2018-06-20T10:19:13.933Z] 10:19:13     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 729, in _send_message
[task 2018-06-20T10:19:13.934Z] 10:19:13     INFO -     raise errors.MarionetteException("Please start a session")
[task 2018-06-20T10:19:13.935Z] 10:19:13     INFO - TEST-INFO took 361708ms
[task 2018-06-20T10:19:13.937Z] 10:19:13     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmpdlQ74o.mozrunner
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_keep_context_after_restart_by_using_context | MarionetteException: Please start a session → Intermittent test_quit_restart.py TestQuitRestart.test_keep_context_after_restart_by_using_context, TestQuitRestart.test_reset_context_after_quit_by_using_context | MarionetteException: Please start a session
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
New log file and snippet with the failure:
https://treeherder.mozilla.org/logviewer.html#?job_id=192385390&repo=autoland&lineNumber=35001

[task 2018-08-06T23:24:00.042Z] 23:24:00     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_keep_context_after_restart_by_using_context
[task 2018-08-06T23:24:00.059Z] 23:24:00     INFO -  1533597840047	Marionette	DEBUG	Closed connection 1
[task 2018-08-06T23:24:00.059Z] 23:24:00     INFO -  1533597840049	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:57378
[task 2018-08-06T23:24:00.063Z] 23:24:00     INFO -  1533597840057	Marionette	TRACE	2 -> [0,1,"WebDriver:NewSession",{}]
[task 2018-08-06T23:24:00.079Z] 23:24:00     INFO -  1533597840072	Marionette	DEBUG	[2147483649] Frame script loaded
[task 2018-08-06T23:24:00.087Z] 23:24:00     INFO -  1533597840081	Marionette	DEBUG	[2147483649] Frame script registered
[task 2018-08-06T23:24:00.103Z] 23:24:00     INFO -  1533597840093	Marionette	TRACE	2 <- [1,1,null,{"sessionId":"46c94803-96a1-48f8-bd9b-a71577bfc083","capabilities":{"browserName":"firefox","browserVersion":"63.0a ... ssID":6907,"moz:profile":"/tmp/tmpGWApmT.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2018-08-06T23:24:00.111Z] 23:24:00     INFO -  1533597840104	Marionette	TRACE	2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2018-08-06T23:24:00.112Z] 23:24:00     INFO -  1533597840107	Marionette	TRACE	2 <- [1,2,null,{"value":null}]
[task 2018-08-06T23:24:00.128Z] 23:24:00     INFO -  1533597840119	Marionette	TRACE	2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2018-08-06T23:24:00.136Z] 23:24:00     INFO -  1533597840128	Marionette	TRACE	2 <- [1,3,null,{"value":null}]
[task 2018-08-06T23:24:00.141Z] 23:24:00     INFO -  1533597840136	Marionette	TRACE	2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2018-08-06T23:24:00.144Z] 23:24:00     INFO -  1533597840141	Marionette	TRACE	2 <- [1,4,null,{"value":null}]
[task 2018-08-06T23:24:00.152Z] 23:24:00     INFO -  1533597840148	Marionette	TRACE	2 -> [0,5,"Marionette:GetContext",{}]
[task 2018-08-06T23:24:00.153Z] 23:24:00     INFO -  1533597840151	Marionette	TRACE	2 <- [1,5,null,{"value":"content"}]
[task 2018-08-06T23:24:00.190Z] 23:24:00     INFO -  1533597840182	Marionette	TRACE	2 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-08-06T23:24:00.190Z] 23:24:00     INFO -  1533597840184	Marionette	TRACE	2 <- [1,6,null,{"value":null}]
[task 2018-08-06T23:24:00.198Z] 23:24:00     INFO -  1533597840193	Marionette	TRACE	2 -> [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":890}]
[task 2018-08-06T23:24:00.214Z] 23:24:00     INFO -  1533597840206	Marionette	TRACE	2 <- [1,7,null,{"value":""}]
[task 2018-08-06T23:24:00.263Z] 23:24:00     INFO -  1533597840258	Marionette	TRACE	2 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2018-08-06T23:24:00.264Z] 23:24:00     INFO -  1533597840260	Marionette	TRACE	2 <- [1,8,null,{"value":null}]
[task 2018-08-06T23:24:00.268Z] 23:24:00     INFO -  1533597840266	Marionette	TRACE	2 -> [0,9,"Marionette:GetContext",{}]
[task 2018-08-06T23:24:00.272Z] 23:24:00     INFO -  1533597840269	Marionette	TRACE	2 <- [1,9,null,{"value":"content"}]
[task 2018-08-06T23:24:00.354Z] 23:24:00     INFO -  1533597840348	Marionette	TRACE	2 -> [0,10,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-08-06T23:24:00.355Z] 23:24:00     INFO -  1533597840349	Marionette	TRACE	2 <- [1,10,null,{"value":null}]
[task 2018-08-06T23:24:00.411Z] 23:24:00     INFO -  1533597840401	Marionette	TRACE	2 -> [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":924}]
[task 2018-08-06T23:24:00.419Z] 23:24:00     INFO -  1533597840413	Marionette	TRACE	2 <- [1,11,null,{"value":null}]
[task 2018-08-06T23:24:00.435Z] 23:24:00     INFO -  1533597840424	Marionette	TRACE	2 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2018-08-06T23:24:00.436Z] 23:24:00     INFO -  1533597840426	Marionette	TRACE	2 <- [1,12,null,{"value":null}]
[task 2018-08-06T23:24:00.501Z] 23:24:00     INFO -  1533597840498	Marionette	TRACE	2 -> [0,13,"WebDriver:GetCurrentURL",{}]
[task 2018-08-06T23:24:00.509Z] 23:24:00     INFO -  1533597840502	Marionette	TRACE	2 <- [1,13,null,{"value":"about:blank"}]
[task 2018-08-06T23:24:00.525Z] 23:24:00     INFO -  1533597840517	Marionette	TRACE	2 -> [0,14,"Marionette:GetContext",{}]
[task 2018-08-06T23:24:00.526Z] 23:24:00     INFO -  1533597840518	Marionette	TRACE	2 <- [1,14,null,{"value":"content"}]
[task 2018-08-06T23:24:00.630Z] 23:24:00     INFO -  1533597840626	Marionette	TRACE	2 -> [0,15,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-08-06T23:24:00.631Z] 23:24:00     INFO -  1533597840629	Marionette	TRACE	2 <- [1,15,null,{"value":null}]
[task 2018-08-06T23:24:00.680Z] 23:24:00     INFO -  1533597840675	Marionette	TRACE	2 -> [0,16,"Marionette:GetContext",{}]
[task 2018-08-06T23:24:00.681Z] 23:24:00     INFO -  1533597840677	Marionette	TRACE	2 <- [1,16,null,{"value":"chrome"}]
[task 2018-08-06T23:24:00.722Z] 23:24:00     INFO -  1533597840721	Marionette	TRACE	2 -> [0,17,"Marionette:GetContext",{}]
[task 2018-08-06T23:24:00.727Z] 23:24:00     INFO -  1533597840722	Marionette	TRACE	2 <- [1,17,null,{"value":"chrome"}]
[task 2018-08-06T23:24:00.745Z] 23:24:00     INFO -  1533597840733	Marionette	TRACE	2 -> [0,18,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-08-06T23:24:00.746Z] 23:24:00     INFO -  1533597840734	Marionette	TRACE	2 <- [1,18,null,{"value":null}]
[task 2018-08-06T23:24:00.748Z] 23:24:00     INFO -  1533597840741	Marionette	TRACE	2 -> [0,19,"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":1059}]
[task 2018-08-06T23:24:00.765Z] 23:24:00     INFO -  1533597840759	Marionette	TRACE	2 <- [1,19,null,{"value":false}]
[task 2018-08-06T23:24:00.767Z] 23:24:00     INFO -  1533597840762	Marionette	TRACE	2 -> [0,20,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-08-06T23:24:00.768Z] 23:24:00     INFO -  1533597840763	Marionette	TRACE	2 <- [1,20,null,{"value":null}]
[task 2018-08-06T23:24:00.777Z] 23:24:00     INFO -  1533597840772	Marionette	TRACE	2 -> [0,21,"Marionette:Quit",{"flags":["eForceQuit","eRestart"]}]
[task 2018-08-06T23:24:00.778Z] 23:24:00     INFO -  1533597840773	Marionette	INFO	Stopped listening on port 2828
[task 2018-08-06T23:24:00.901Z] 23:24:00     INFO -  1533597840897	Marionette	TRACE	2 <- [1,21,null,{"cause":"restart"}]
[task 2018-08-06T23:24:01.000Z] 23:24:01     INFO -  1533597840997	Marionette	DEBUG	Closed connection 2
[task 2018-08-06T23:24:01.590Z] 23:24:01     INFO -  1533597841586	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-08-06T23:24:01.590Z] 23:24:01     INFO -  1533597841586	Marionette	DEBUG	Remote service is inactive
[task 2018-08-06T23:24:02.278Z] 23:24:02     INFO -  *** You are running in headless mode.
[task 2018-08-06T23:30:02.058Z] 23:30:02     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_keep_context_after_restart_by_using_context | MarionetteException: Please start a session
[task 2018-08-06T23:30:02.058Z] 23:30:02     INFO - Traceback (most recent call last):
[task 2018-08-06T23:30:02.058Z] 23:30:02     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2018-08-06T23:30:02.059Z] 23:30:02     INFO -     testMethod()
[task 2018-08-06T23:30:02.059Z] 23:30:02     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py", line 359, in test_keep_context_after_restart_by_using_context
[task 2018-08-06T23:30:02.060Z] 23:30:02     INFO -     "Not in chrome context after a restart with using_context")
[task 2018-08-06T23:30:02.060Z] 23:30:02     INFO -   File "/usr/lib/python2.7/contextlib.py", line 35, in __exit__
[task 2018-08-06T23:30:02.060Z] 23:30:02     INFO -     self.gen.throw(type, value, traceback)
[task 2018-08-06T23:30:02.062Z] 23:30:02     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1449, in using_context
[task 2018-08-06T23:30:02.063Z] 23:30:02     INFO -     self.set_context(scope)
[task 2018-08-06T23:30:02.064Z] 23:30:02     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1426, in set_context
[task 2018-08-06T23:30:02.064Z] 23:30:02     INFO -     {"value": context})
[task 2018-08-06T23:30:02.065Z] 23:30:02     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2018-08-06T23:30:02.066Z] 23:30:02     INFO -     return func(*args, **kwargs)
[task 2018-08-06T23:30:02.066Z] 23:30:02     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 745, in _send_message
[task 2018-08-06T23:30:02.067Z] 23:30:02     INFO -     raise errors.MarionetteException("Please start a session")
[task 2018-08-06T23:30:02.067Z] 23:30:02     INFO - TEST-INFO took 362014ms
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
No more failures since Oct 2nd, which was 4 days before my patch on bug 1433873 landed. But majorly it was failing due to the hang for ASAN builds anyway. I would call this finally fixed by bug 1433873.
Assignee: nobody → hskupin
Target Milestone: --- → mozilla64
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.