Closed Bug 1467740 Opened 2 years ago Closed 2 years ago

Intermittent testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_random_profile_name | IOError: Process killed after 120s because no connection to Marionette server could...

Categories

(Testing :: Marionette, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

Filed by: aiakab [at] mozilla.com

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

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

08:51:29     INFO -  TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_random_profile_name
08:51:29     INFO -  1528447889168	Marionette	DEBUG	Closed connection 3
08:51:29     INFO -  1528447889172	Marionette	DEBUG	Accepted connection 4 from 127.0.0.1:51901
08:51:29     INFO -  1528447889174	Marionette	TRACE	4 -> [0,1,"WebDriver:NewSession",{}]
08:51:29     INFO -  1528447889180	Marionette	DEBUG	Register listener.js for window 4294967297
08:51:29     INFO -  1528447889185	Marionette	TRACE	4 <- [1,1,null,{"sessionId":"6a66f7be-6bb9-461e-882f-cf6726f9c27c","capabilities":{"browserName":"firefox","browserVersion":"62.0a ... _1528445624\\AppData\\Local\\Temp\\tmpkgvrmw.$¢€ἶA","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
08:51:29     INFO -  1528447889188	Marionette	TRACE	4 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
08:51:29     INFO -  1528447889190	Marionette	TRACE	4 <- [1,2,null,{"value":null}]
08:51:29     INFO -  1528447889192	Marionette	TRACE	4 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
08:51:29     INFO -  1528447889193	Marionette	TRACE	4 <- [1,3,null,{"value":null}]
08:51:29     INFO -  1528447889196	Marionette	TRACE	4 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
08:51:29     INFO -  1528447889199	Marionette	TRACE	4 <- [1,4,null,{"value":null}]
08:51:29     INFO -  1528447889206	Marionette	TRACE	4 -> [0,5,"WebDriver:DeleteSession",{}]
08:51:29     INFO -  1528447889208	Marionette	TRACE	4 <- [1,5,null,{"value":null}]
08:51:29     INFO -  Application command: Z:\task_1528445624\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\task_1528445624\appdata\local\temp\tmp3uxgbs.mozrunner
08:51:29     INFO -  *** You are running in headless mode.
08:51:31     INFO -  1528447891506	Marionette	DEBUG	Received observer notification profile-after-change
08:51:31     INFO -  1528447891701	Marionette	DEBUG	Received observer notification command-line-startup
08:51:31     INFO -  1528447891701	Marionette	DEBUG	Received observer notification nsPref:changed
08:51:31     INFO -  1528447891701	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
08:53:29    ERROR -  TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_random_profile_name | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors
08:53:29     INFO -  Traceback (most recent call last):
08:53:29     INFO -    File "Z:\task_1528445624\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
08:53:29     INFO -      testMethod()
08:53:29     INFO -    File "Z:\task_1528445624\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py", line 164, in test_new_random_profile_name
08:53:29     INFO -      self.marionette.start_session()
08:53:29     INFO -    File "Z:\task_1528445624\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
08:53:29     INFO -      return func(*args, **kwargs)
08:53:29     INFO -    File "Z:\task_1528445624\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1210, in start_session
08:53:29     INFO -      self.start_binary(timeout)
08:53:29     INFO -    File "Z:\task_1528445624\build\venv\lib\site-packages\marionette_driver\marionette.py", line 639, in start_binary
08:53:29     INFO -      reraise(IOError, msg.format(timeout), tb)
08:53:29     INFO -    File "Z:\task_1528445624\build\venv\lib\site-packages\marionette_driver\marionette.py", line 630, in start_binary
08:53:29     INFO -      self.raise_for_port(timeout=timeout)
08:53:29     INFO -    File "Z:\task_1528445624\build\venv\lib\site-packages\marionette_driver\marionette.py", line 710, in raise_for_port
08:53:29     INFO -      self.host, self.port))
08:53:29     INFO -  TEST-INFO took 120639ms
08:53:29     INFO -  Application command: Z:\task_1528445624\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\task_1528445624\appdata\local\temp\tmpwqdjrn.mozrunner
08:53:30     INFO -  *** You are running in headless mode.
08:53:31     INFO -  1528448011803	Marionette	DEBUG	Received observer notification profile-after-change
08:53:32     INFO -  1528448011996	Marionette	DEBUG	Received observer notification command-line-startup
08:53:32     INFO -  1528448011996	Marionette	DEBUG	Received observer notification nsPref:changed
08:53:32     INFO -  1528448011997	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
08:53:34     INFO -  1528448014969	Marionette	DEBUG	Received observer notification sessionstore-windows-restored
08:53:34     INFO -  1528448014970	Marionette	DEBUG	Waiting for delayed startup...
08:53:36     INFO -  1528448016195	Marionette	DEBUG	Waiting for startup tests...
08:53:36     INFO -  1528448016394	Marionette	INFO	Listening on port 2828
08:53:36     INFO -  1528448016395	Marionette	DEBUG	Remote service is active
08:53:36     INFO -  1528448016431	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:52176
08:53:36     INFO -  1528448016442	Marionette	DEBUG	Closed connection 0
08:53:36     INFO -  1528448016444	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:52177
08:53:36     INFO -  1528448016458	Marionette	TRACE	1 -> [0,1,"WebDriver:NewSession",{}]
08:53:36     INFO -  1528448016581	Marionette	DEBUG	Register listener.js for window 4294967297
08:53:36     INFO -  1528448016611	Marionette	TRACE	1 <- [1,1,null,{"sessionId":"5fa555c6-3d1e-4465-bad6-c5d0a91b82bf","capabilities":{"browserName":"firefox","browserVersion":"62.0a ... 8445624\\AppData\\Local\\Temp\\tmpwqdjrn.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
08:53:36     INFO -  1528448016630	Marionette	TRACE	1 -> [0,2,"WebDriver:DeleteSession",{}]
08:53:36     INFO -  TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithoutWorkspace.test_replace_with_current_profile
08:53:36     INFO -  1528448016634	Marionette	TRACE	1 <- [1,2,null,{"value":null}]
08:53:36     INFO -  1528448016639	Marionette	DEBUG	Closed connection 1
08:53:36     INFO -  1528448016640	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:52178
08:53:36     INFO -  1528448016647	Marionette	TRACE	2 -> [0,1,"WebDriver:NewSession",{}]
08:53:36     INFO -  1528448016653	Marionette	DEBUG	Register listener.js for window 4294967297
08:53:36     INFO -  1528448016660	Marionette	TRACE	2 <- [1,1,null,{"sessionId":"ba6a5578-bde6-41d4-9911-fffadc728ed3","capabilities":{"browserName":"firefox","browserVersion":"62.0a ... 8445624\\AppData\\Local\\Temp\\tmpwqdjrn.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
08:53:36     INFO -  1528448016670	Marionette	TRACE	2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
08:53:36     INFO -  1528448016671	Marionette	TRACE	2 <- [1,2,null,{"value":null}]
08:53:36     INFO -  1528448016677	Marionette	TRACE	2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
08:53:36     INFO -  1528448016678	Marionette	TRACE	2 <- [1,3,null,{"value":null}]
08:53:36     INFO -  1528448016685	Marionette	TRACE	2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
08:53:36     INFO -  1528448016687	Marionette	TRACE	2 <- [1,4,null,{"value":null}]
08:53:36     INFO -  1528448016694	Marionette	TRACE	2 -> [0,5,"WebDriver:DeleteSession",{}]
08:53:36     INFO -  1528448016697	Marionette	TRACE	2 <- [1,5,null,{"value":null}]
08:53:36     INFO -  Application command: Z:\task_1528445624\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\task_1528445624\appdata\local\temp\tmpwqdjrn.mozrunner
08:53:37     INFO -  *** You are running in headless mode.
No "sessionstore-windows-restored" notification. So it depends on bug 1382162.
Depends on: 1382162
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=187142379&repo=autoland&lineNumber=33093

    INFO -  Application command: Z:\task_1531138823\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\task_1531138823\appdata\local\temp\tmpvx9gnx.mozrunner
12:29:17     INFO -  1531139357630	Marionette	DEBUG	Received observer notification profile-after-change
12:31:17    ERROR -  TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_random_profile_name | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors
12:31:17     INFO -  Traceback (most recent call last):
12:31:17     INFO -    File "Z:\task_1531138823\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
12:31:17     INFO -      testMethod()
12:31:17     INFO -    File "Z:\task_1531138823\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py", line 164, in test_new_random_profile_name
12:31:17     INFO -      self.marionette.start_session()
12:31:17     INFO -    File "Z:\task_1531138823\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
12:31:17     INFO -      return func(*args, **kwargs)
12:31:17     INFO -    File "Z:\task_1531138823\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1227, in start_session
12:31:17     INFO -      self.start_binary(timeout)
12:31:17     INFO -    File "Z:\task_1531138823\build\venv\lib\site-packages\marionette_driver\marionette.py", line 660, in start_binary
12:31:17     INFO -      reraise(IOError, msg.format(timeout), tb)
12:31:17     INFO -    File "Z:\task_1531138823\build\venv\lib\site-packages\marionette_driver\marionette.py", line 651, in start_binary
12:31:17     INFO -      self.raise_for_port(timeout=timeout)
12:31:17     INFO -    File "Z:\task_1531138823\build\venv\lib\site-packages\marionette_driver\marionette.py", line 731, in raise_for_port
12:31:17     INFO -      self.host, self.port))
Status: RESOLVED → REOPENED
Flags: needinfo?(dburns)
Resolution: INCOMPLETE → ---
I triggered a few of these jobs in the same push and it appears to
happen very infrequently.  Previous OF statistics on this bug
indicate it happens at a 0.001 rate, which is extremely infrequent.

As whimboo noted above, it depends on
https://bugzilla.mozilla.org/show_bug.cgi?id=1382162.
Flags: needinfo?(dburns)
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.