1528287 - Intermittent testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestQuitRestartWithWorkspace.test_quit_clean_creates_new_profile | IOError: Process killed after 120s because no connection to Marionette server could be

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

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

https://treeherder.mozilla.org/logviewer.html#?job_id=228668056&repo=mozilla-inbound

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

15:43:32 INFO - TEST-PASS | testing\marionette\harness\marionette_harness\tests\unit\test_click_scrolling.py TestClickScrolling.test_should_scroll_to_click_on_an_element_hidden_by_overflow | took 78ms
15:43:32 INFO - 1550245412849 Marionette DEBUG Closed connection 252
15:43:32 INFO - TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestQuitRestartWithWorkspace.test_quit_clean_creates_new_profile
15:43:32 INFO - 1550245412858 Marionette DEBUG Accepted connection 253 from 127.0.0.1:51505
15:43:32 INFO - 1550245412860 Marionette DEBUG 253 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
15:43:32 INFO - 1550245412861 Marionette TRACE [55834574849] Frame script loaded
15:43:32 INFO - 1550245412862 Marionette TRACE [55834574849] Frame script registered
15:43:32 INFO - 1550245412863 Marionette DEBUG 253 <- [1,1,null,{"sessionId":"aac6f1cb-4ea2-436c-8f53-c7075338a45a","capabilities":{"browserName":"firefox","browserVersion":"67.0a ... p\\tmpf8olci.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
15:43:32 INFO - 1550245412865 Marionette DEBUG 253 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
15:43:32 INFO - 1550245412865 Marionette DEBUG 253 <- [1,2,null,{"value":null}]
15:43:32 INFO - 1550245412866 Marionette DEBUG 253 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
15:43:32 INFO - 1550245412867 Marionette DEBUG 253 <- [1,3,null,{"value":null}]
15:43:32 INFO - 1550245412868 Marionette DEBUG 253 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
15:43:32 INFO - 1550245412868 Marionette DEBUG 253 <- [1,4,null,{"value":null}]
15:43:33 INFO - Application command: Z:\task_1550244950\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\task_1550244950\appdata\local\temp\tmpemfkdc\tmprobt3w.mozrunner
15:43:33 INFO - *** You are running in headless mode.
15:43:33 INFO - 1550245413461 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
15:43:33 INFO - 1550245413461 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
15:43:33 INFO - 1550245413461 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
15:43:33 INFO - 1550245413612 Marionette TRACE Received observer notification profile-after-change
15:43:33 INFO - 1550245413639 Marionette TRACE Received observer notification toplevel-window-ready
15:43:33 INFO - 1550245413681 Marionette TRACE Received observer notification command-line-startup
15:43:33 INFO - 1550245413681 Marionette TRACE Received observer notification nsPref:changed
15:43:33 INFO - 1550245413681 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
15:45:33 ERROR - TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestQuitRestartWithWorkspace.test_quit_clean_creates_new_profile | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors
15:45:33 INFO - Traceback (most recent call last):
15:45:33 INFO - File "Z:\task_1550244950\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
15:45:33 INFO - testMethod()
15:45:33 INFO - File "Z:\task_1550244950\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py", line 120, in test_quit_clean_creates_new_profile
15:45:33 INFO - self.marionette.start_session()
15:45:33 INFO - File "Z:\task_1550244950\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
15:45:33 INFO - return func(*args, **kwargs)
15:45:33 INFO - File "Z:\task_1550244950\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1269, in start_session
15:45:33 INFO - self.start_binary(timeout)
15:45:33 INFO - File "Z:\task_1550244950\build\venv\lib\site-packages\marionette_driver\marionette.py", line 658, in start_binary
15:45:33 INFO - reraise(IOError, msg.format(timeout), tb)
15:45:33 INFO - File "Z:\task_1550244950\build\venv\lib\site-packages\marionette_driver\marionette.py", line 649, in start_binary
15:45:33 INFO - self.raise_for_port(timeout=timeout)
15:45:33 INFO - File "Z:\task_1550244950\build\venv\lib\site-packages\marionette_driver\marionette.py", line 735, in raise_for_port
15:45:33 INFO - self.host, self.port))
15:45:33 INFO - TEST-INFO took 120419ms
15:45:33 INFO - Application command: Z:\task_1550244950\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\task_1550244950\appdata\local\temp\tmpemfkdc\tmpfrjis7.mozrunner
15:45:33 INFO - *** You are running in headless mode.
15:45:33 INFO - 1550245533726 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
15:45:33 INFO - 1550245533726 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
15:45:33 INFO - 1550245533726 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
15:45:33 INFO - 1550245533879 Marionette TRACE Received observer notification profile-after-change
15:45:33 INFO - 1550245533915 Marionette TRACE Received observer notification toplevel-window-ready
15:45:33 INFO - 1550245533957 Marionette TRACE Received observer notification command-line-startup
15:45:33 INFO - 1550245533957 Marionette TRACE Received observer notification nsPref:changed
15:45:33 INFO - 1550245533957 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
15:45:34 INFO - 1550245534088 Marionette TRACE Received observer notification toplevel-window-ready
15:45:34 INFO - 1550245534892 Marionette TRACE Received observer notification sessionstore-windows-restored
15:45:34 INFO - 1550245534892 Marionette TRACE Received observer notification marionette-startup-requested
15:45:34 INFO - 1550245534893 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
15:45:35 INFO - 1550245535208 Marionette TRACE All scripts recorded.
15:45:35 INFO - 1550245535249 Marionette INFO Listening on port 2828
15:45:35 INFO - 1550245535250 Marionette DEBUG Remote service is active
15:45:35 INFO - 1550245535486 Marionette DEBUG Accepted connection 0 from 127.0.0.1:51745
15:45:35 INFO - 1550245535586 Marionette DEBUG Closed connection 0
15:45:35 INFO - 1550245535586 Marionette DEBUG Accepted connection 1 from 127.0.0.1:51752
15:45:35 INFO - 1550245535686 Marionette DEBUG Accepted connection 2 from 127.0.0.1:51755
15:45:35 INFO - 1550245535688 Marionette DEBUG Closed connection 2
15:45:35 INFO - 1550245535688 Marionette DEBUG Closed connection 1
15:45:35 INFO - 1550245535689 Marionette DEBUG Accepted connection 3 from 127.0.0.1:51756
15:45:35 INFO - 1550245535690 Marionette DEBUG 3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
15:45:35 INFO - 1550245535724 Marionette TRACE [6442450945] Frame script loaded
15:45:35 INFO - 1550245535726 Marionette TRACE [6442450945] Frame script registered
15:45:35 INFO - 1550245535730 Marionette DEBUG 3 <- [1,1,null,{"sessionId":"0ec891a5-b2e0-4fb2-82b0-fbb8baadf6ab","capabilities":{"browserName":"firefox","browserVersion":"67.0a ... c\\tmpfrjis7.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-inbound: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1528287&startday=2019-02-11&endday=2019-02-17&tree=all

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Missing "sessionstore-windows-restored" notification during startup of Firefox. This is tracked on bug 1382162.

Comment 3

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 4

[Andreea Pavel [:apavel]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=237984584&repo=autoland&lineNumber=31509

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-aarch64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1528287&startday=2019-04-01&endday=2019-04-07&tree=all

Comment 6

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 7

[Bogdan Tara[:bogdan_tara | bogdant]]

This is still happening.
Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=296259702&repo=mozilla-central&lineNumber=31874

[task 2020-04-04T10:04:49.673Z] 10:04:49     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_clean_creates_new_profile
[task 2020-04-04T10:04:49.675Z] 10:04:49     INFO -  1585994689673	Marionette	DEBUG	Accepted connection 251 from 127.0.0.1:51699
[task 2020-04-04T10:04:49.680Z] 10:04:49     INFO -  1585994689676	Marionette	DEBUG	251 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-04-04T10:04:49.680Z] 10:04:49     INFO -  1585994689678	Marionette	TRACE	[161] Frame script loaded
[task 2020-04-04T10:04:49.681Z] 10:04:49     INFO -  1585994689679	Marionette	TRACE	[161] Frame script registered
[task 2020-04-04T10:04:49.681Z] 10:04:49     INFO -  1585994689680	Marionette	DEBUG	251 <- [1,1,null,{"sessionId":"b12e816d-b394-4828-8486-d1f9e0ce80c9","capabilities":{"browserName":"firefox","browserVersion":"76.0a ... p\\tmpt3563t.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-04-04T10:04:49.683Z] 10:04:49     INFO -  1585994689682	Marionette	DEBUG	251 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-04-04T10:04:49.683Z] 10:04:49     INFO -  1585994689682	Marionette	DEBUG	251 <- [1,2,null,{"value":null}]
[task 2020-04-04T10:04:49.685Z] 10:04:49     INFO -  1585994689684	Marionette	DEBUG	251 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-04-04T10:04:49.685Z] 10:04:49     INFO -  1585994689684	Marionette	DEBUG	251 <- [1,3,null,{"value":null}]
[task 2020-04-04T10:04:49.687Z] 10:04:49     INFO -  1585994689686	Marionette	DEBUG	251 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-04-04T10:04:49.688Z] 10:04:49     INFO -  1585994689686	Marionette	DEBUG	251 <- [1,4,null,{"value":null}]
[task 2020-04-04T10:04:49.874Z] 10:04:49     INFO -  Application command: Z:\task_1585994260\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\task_1585994260\appdata\local\temp\tmpfax4l9\tmppluny0.mozrunner
[task 2020-04-04T10:04:50.074Z] 10:04:50     INFO -  DEBUG: Adding blocker OS.File: flush pending requests, warn about unclosed files, shut down service. for phase web-workers-shutdown
[task 2020-04-04T10:04:50.074Z] 10:04:50     INFO -  DEBUG: Adding blocker OS.File: flush I/O queued before profileBeforeChange for phase profile-before-change
[task 2020-04-04T10:04:50.074Z] 10:04:50     INFO -  DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2020-04-04T10:04:50.104Z] 10:04:50     INFO -  DEBUG: Adding blocker ClientManagerService: start destroying IPC actors early for phase xpcom-will-shutdown
[task 2020-04-04T10:04:50.167Z] 10:04:50     INFO -  DEBUG: Adding blocker Flush WebExtension StartupCache for phase profile-before-change
[task 2020-04-04T10:04:50.267Z] 10:04:50     INFO -  1585994690259	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Invalid extension permission: networkStatus
[task 2020-04-04T10:04:50.267Z] 10:04:50     INFO -  DEBUG: Adding blocker JSON store: writing data for phase profile-before-change
[task 2020-04-04T10:04:50.289Z] 10:04:50     INFO -  1585994690285	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
[task 2020-04-04T10:04:50.289Z] 10:04:50     INFO -  1585994690286	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Invalid extension permission: telemetry
[task 2020-04-04T10:04:50.289Z] 10:04:50     INFO -  1585994690286	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
[task 2020-04-04T10:04:50.289Z] 10:04:50     INFO -  1585994690286	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
[task 2020-04-04T10:04:50.308Z] 10:04:50     INFO -  DEBUG: Adding blocker JSON store: writing data for phase AddonManager: Waiting for providers to shut down.
[task 2020-04-04T10:04:50.313Z] 10:04:50     INFO -  DEBUG: Adding blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2020-04-04T10:04:50.313Z] 10:04:50     INFO -  DEBUG: Completed blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2020-04-04T10:04:50.322Z] 10:04:50     INFO -  DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2020-04-04T10:04:50.322Z] 10:04:50     INFO -  DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2020-04-04T10:04:50.322Z] 10:04:50     INFO -  DEBUG: Adding blocker PluginProvider for phase AddonManager: Waiting for providers to shut down.
[task 2020-04-04T10:04:50.341Z] 10:04:50     INFO -  DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2020-04-04T10:04:50.341Z] 10:04:50     INFO -  DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change for phase OS.File: Waiting for clients before profileBeforeChange
[task 2020-04-04T10:04:50.343Z] 10:04:50     INFO -  1585994690341	Marionette	TRACE	Marionette enabled
[task 2020-04-04T10:04:50.343Z] 10:04:50     INFO -  1585994690341	Marionette	TRACE	Received observer notification profile-after-change
[task 2020-04-04T10:04:50.434Z] 10:04:50     INFO -  DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2020-04-04T10:04:50.444Z] 10:04:50     INFO -  DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2020-04-04T10:04:50.462Z] 10:04:50     INFO -  DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2020-04-04T10:04:50.462Z] 10:04:50     INFO -  1585994690452	Marionette	TRACE	Received observer notification command-line-startup
[task 2020-04-04T10:04:50.522Z] 10:04:50     INFO -  1585994690508	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-04-04T10:06:50.181Z] 10:06:50    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py TestQuitRestartWithWorkspace.test_quit_clean_creates_new_profile | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors
[task 2020-04-04T10:06:50.181Z] 10:06:50     INFO -  Traceback (most recent call last):
[task 2020-04-04T10:06:50.181Z] 10:06:50     INFO -    File "Z:\task_1585994260\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
[task 2020-04-04T10:06:50.181Z] 10:06:50     INFO -      testMethod()
[task 2020-04-04T10:06:50.181Z] 10:06:50     INFO -    File "Z:\task_1585994260\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py", line 120, in test_quit_clean_creates_new_profile
[task 2020-04-04T10:06:50.181Z] 10:06:50     INFO -      self.marionette.start_session()
[task 2020-04-04T10:06:50.181Z] 10:06:50     INFO -    File "Z:\task_1585994260\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2020-04-04T10:06:50.181Z] 10:06:50     INFO -      return func(*args, **kwargs)
[task 2020-04-04T10:06:50.181Z] 10:06:50     INFO -    File "Z:\task_1585994260\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1102, in start_session
[task 2020-04-04T10:06:50.181Z] 10:06:50     INFO -      self.start_binary(timeout)
[task 2020-04-04T10:06:50.182Z] 10:06:50     INFO -    File "Z:\task_1585994260\build\venv\lib\site-packages\marionette_driver\marionette.py", line 490, in start_binary
[task 2020-04-04T10:06:50.182Z] 10:06:50     INFO -      reraise(IOError, IOError(msg.format(timeout)), sys.exc_info()[2])
[task 2020-04-04T10:06:50.182Z] 10:06:50     INFO -    File "Z:\task_1585994260\build\venv\lib\site-packages\marionette_driver\marionette.py", line 482, in start_binary
[task 2020-04-04T10:06:50.182Z] 10:06:50     INFO -      self.raise_for_port(timeout=timeout)
[task 2020-04-04T10:06:50.182Z] 10:06:50     INFO -    File "Z:\task_1585994260\build\venv\lib\site-packages\marionette_driver\marionette.py", line 568, in raise_for_port
[task 2020-04-04T10:06:50.182Z] 10:06:50     INFO -      self.host, self.port))
[task 2020-04-04T10:06:50.182Z] 10:06:50     INFO -  TEST-INFO took 120508ms

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1528287&startday=2020-03-30&endday=2020-04-05&tree=all

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform breakdown:

• macosx1014-64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1528287&startday=2020-08-03&endday=2020-08-09&tree=all

Comment 11

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.