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

Status: RESOLVED DUPLICATE of bug 1466790

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

Description

[Treeherder Bug Filer]

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

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

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

23:20:59 INFO - TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_named_profile_unicode
23:20:59 INFO - 1553901659491 Marionette DEBUG Closed connection 3
23:20:59 INFO - 1553901659492 Marionette DEBUG Accepted connection 4 from 127.0.0.1:51848
23:20:59 INFO - 1553901659493 Marionette DEBUG 4 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
23:20:59 INFO - 1553901659495 Marionette TRACE [6442450945] Frame script loaded
23:20:59 INFO - 1553901659496 Marionette TRACE [6442450945] Frame script registered
23:20:59 INFO - 1553901659497 Marionette DEBUG 4 <- [1,1,null,{"sessionId":"490801f7-a155-4bb2-9e3c-d14256418f77","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... Temp\\tmppqilvj.foobar","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
23:20:59 INFO - 1553901659498 Marionette DEBUG 4 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
23:20:59 INFO - 1553901659499 Marionette DEBUG 4 <- [1,2,null,{"value":null}]
23:20:59 INFO - 1553901659500 Marionette DEBUG 4 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
23:20:59 INFO - 1553901659501 Marionette DEBUG 4 <- [1,3,null,{"value":null}]
23:20:59 INFO - 1553901659502 Marionette DEBUG 4 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
23:20:59 INFO - 1553901659503 Marionette DEBUG 4 <- [1,4,null,{"value":null}]
23:20:59 INFO - Application command: Z:\task_1553901222\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\task_1553901222\appdata\local\temp\tmpunrlub.$¢€🍪
23:20:59 INFO - *** You are running in headless mode.
23:21:00 INFO - 1553901660024 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
23:21:00 INFO - 1553901660024 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
23:21:00 INFO - 1553901660024 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
23:21:00 INFO - 1553901660150 Marionette TRACE Received observer notification profile-after-change
23:21:00 INFO - 1553901660173 Marionette TRACE Received observer notification toplevel-window-ready
23:21:00 INFO - 1553901660221 Marionette TRACE Received observer notification command-line-startup
23:21:00 INFO - 1553901660221 Marionette TRACE Received observer notification nsPref:changed
23:21:00 INFO - 1553901660221 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
23:22:59 ERROR - TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_named_profile_unicode | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors
23:22:59 INFO - Traceback (most recent call last):
23:22:59 INFO - File "Z:\task_1553901222\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
23:22:59 INFO - testMethod()
23:22:59 INFO - File "Z:\task_1553901222\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py", line 180, in test_new_named_profile_unicode
23:22:59 INFO - self.marionette.start_session()
23:22:59 INFO - File "Z:\task_1553901222\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
23:22:59 INFO - return func(*args, **kwargs)
23:22:59 INFO - File "Z:\task_1553901222\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1103, in start_session
23:22:59 INFO - self.start_binary(timeout)
23:22:59 INFO - File "Z:\task_1553901222\build\venv\lib\site-packages\marionette_driver\marionette.py", line 491, in start_binary
23:22:59 INFO - reraise(IOError, msg.format(timeout), tb)
23:22:59 INFO - File "Z:\task_1553901222\build\venv\lib\site-packages\marionette_driver\marionette.py", line 482, in start_binary
23:22:59 INFO - self.raise_for_port(timeout=timeout)
23:22:59 INFO - File "Z:\task_1553901222\build\venv\lib\site-packages\marionette_driver\marionette.py", line 569, in raise_for_port
23:22:59 INFO - self.host, self.port))
23:22:59 INFO - TEST-INFO took 120407ms
23:22:59 INFO - Application command: Z:\task_1553901222\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\task_1553901222\appdata\local\temp\tmpxobpgs.mozrunner
23:22:59 INFO - *** You are running in headless mode.
23:23:00 INFO - 1553901780389 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
23:23:00 INFO - 1553901780389 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
23:23:00 INFO - 1553901780389 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
23:23:00 INFO - 1553901780545 Marionette TRACE Received observer notification profile-after-change
23:23:00 INFO - 1553901780567 Marionette TRACE Received observer notification toplevel-window-ready
23:23:00 INFO - 1553901780616 Marionette TRACE Received observer notification command-line-startup
23:23:00 INFO - 1553901780616 Marionette TRACE Received observer notification nsPref:changed
23:23:00 INFO - 1553901780616 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
23:23:00 INFO - 1553901780759 Marionette TRACE Received observer notification toplevel-window-ready
23:23:01 INFO - JavaScript warning: chrome://global/content/bindings/tabbox.xml, line 162: Array.forEach is deprecated; use Array.prototype.forEach instead
23:23:01 INFO - JavaScript warning: chrome://browser/content/tabbrowser.js, line 239: Array.filter is deprecated; use Array.prototype.filter instead
23:23:01 INFO - JavaScript warning: chrome://browser/content/tabbrowser.js, line 4834: Array.unshift is deprecated; use Array.prototype.unshift instead
23:23:01 INFO - JavaScript warning: resource://gre/modules/UrlClassifierLib.jsm, line 34: Array.slice is deprecated; use Array.prototype.slice instead
23:23:01 INFO - 1553901781929 Marionette TRACE Received observer notification marionette-startup-requested
23:23:01 INFO - 1553901781930 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
23:23:01 INFO - 1553901781938 Marionette TRACE All scripts recorded.
23:23:02 INFO - 1553901781988 Marionette INFO Listening on port 2828
23:23:02 INFO - 1553901781989 Marionette DEBUG Remote service is active
23:23:02 INFO - 1553901782108 Marionette DEBUG Accepted connection 0 from 127.0.0.1:52088
23:23:02 INFO - 1553901782208 Marionette DEBUG Closed connection 0
23:23:02 INFO - 1553901782209 Marionette DEBUG Accepted connection 1 from 127.0.0.1:52094
23:23:02 INFO - 1553901782315 Marionette DEBUG Accepted connection 2 from 127.0.0.1:52100
23:23:02 INFO - 1553901782316 Marionette DEBUG Closed connection 2
23:23:02 INFO - 1553901782317 Marionette DEBUG Closed connection 1
23:23:02 INFO - 1553901782317 Marionette DEBUG Accepted connection 3 from 127.0.0.1:52101
23:23:02 INFO - 1553901782319 Marionette DEBUG 3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
23:23:02 INFO - 1553901782343 Marionette TRACE [6442450945] Frame script loaded
23:23:02 INFO - 1553901782345 Marionette TRACE [6442450945] Frame script registered
23:23:02 INFO - 1553901782349 Marionette DEBUG 3 <- [1,1,null,{"sessionId":"6e356803-66f4-416a-b795-057403623886","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... p\\tmpxobpgs.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
23:23:02 INFO - 1553901782354 Marionette DEBUG 3 -> [0,2,"WebDriver:DeleteSession",{}]
23:23:02 INFO - 1553901782355 Marionette DEBUG 3 <- [1,2,null,{"value":null}]
23:23:02 INFO - TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_named_profile_unicode_escape_characters
23:23:02 INFO - 1553901782360 Marionette DEBUG Closed connection 3
23:23:02 INFO - 1553901782361 Marionette DEBUG Accepted connection 4 from 127.0.0.1:52102
23:23:02 INFO - 1553901782362 Marionette DEBUG 4 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
23:23:02 INFO - 1553901782363 Marionette TRACE [6442450945] Frame script loaded
23:23:02 INFO - 1553901782364 Marionette TRACE [6442450945] Frame script registered
23:23:02 INFO - 1553901782365 Marionette DEBUG 4 <- [1,1,null,{"sessionId":"b6e1c5fe-7868-4836-9b0d-6cb72e96834e","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... p\\tmpxobpgs.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
23:23:02 INFO - 1553901782367 Marionette DEBUG 4 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
23:23:02 INFO - 1553901782368 Marionette DEBUG 4 <- [1,2,null,{"value":null}]
23:23:02 INFO - 1553901782369 Marionette DEBUG 4 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
23:23:02 INFO - 1553901782369 Marionette DEBUG 4 <- [1,3,null,{"value":null}]
23:23:02 INFO - 1553901782370 Marionette DEBUG 4 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
23:23:02 INFO - 1553901782371 Marionette DEBUG 4 <- [1,4,null,{"value":null}]
23:23:02 INFO - Application command: Z:\task_1553901222\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\task_1553901222\appdata\local\temp\tmpdq1kwn.$¢€ἶA
23:23:02 INFO - *** You are running in headless mode.
23:23:02 INFO - 1553901782876 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: mozillaAddons
23:23:02 INFO - 1553901782876 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: resource://pdf.js/
23:23:02 INFO - 1553901782876 [e-mail] WARN Loading extension '[e-mail]': Reading manifest: Invalid extension permission: about:reader*
23:23:03 INFO - 1553901782998 Marionette TRACE Received observer notification profile-after-change
23:23:03 INFO - 1553901783018 Marionette TRACE Received observer notification toplevel-window-ready
23:23:03 INFO - 1553901783063 Marionette TRACE Received observer notification command-line-startup
23:23:03 INFO - 1553901783063 Marionette TRACE Received observer notification nsPref:changed
23:23:03 INFO - 1553901783063 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
23:23:03 INFO - 1553901783190 Marionette TRACE Received observer notification toplevel-window-ready
23:23:03 INFO - JavaScript warning: chrome://global/content/bindings/tabbox.xml, line 162: Array.forEach is deprecated; use Array.prototype.forEach instead
23:23:03 INFO - JavaScript warning: chrome://browser/content/browser-ctrlTab.js, line 568: Array.filter is deprecated; use Array.prototype.filter instead
23:23:03 INFO - JavaScript warning: chrome://browser/content/tabbrowser.js, line 4834: Array.unshift is deprecated; use Array.prototype.unshift instead
23:23:04 INFO - JavaScript warning: resource://gre/modules/UrlClassifierLib.jsm, line 34: Array.slice is deprecated; use Array.prototype.slice instead
23:23:04 INFO - 1553901784363 Marionette TRACE Received observer notification marionette-startup-requested
23:23:04 INFO - 1553901784363 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
23:23:04 INFO - 1553901784367 Marionette TRACE All scripts recorded.
23:23:04 INFO - 1553901784406 Marionette INFO Listening on port 2828
23:23:04 INFO - 1553901784407 Marionette DEBUG Remote service is active
23:23:04 INFO - 1553901784680 Marionette DEBUG Accepted connection 0 from 127.0.0.1:52113
23:23:04 INFO - 1553901784779 Marionette DEBUG Closed connection 0
23:23:04 INFO - 1553901784785 Marionette DEBUG Accepted connection 1 from 127.0.0.1:52118
23:23:04 INFO - 1553901784880 Marionette DEBUG Accepted connection 2 from 127.0.0.1:52122
23:23:04 INFO - 1553901784881 Marionette DEBUG Closed connection 2
23:23:04 INFO - 1553901784882 Marionette DEBUG Closed connection 1
23:23:04 INFO - 1553901784882 Marionette DEBUG Accepted connection 3 from 127.0.0.1:52123
23:23:04 INFO - 1553901784884 Marionette DEBUG 3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
23:23:04 INFO - 1553901784904 Marionette TRACE [6442450945] Frame script loaded
23:23:04 INFO - 1553901784905 Marionette TRACE [6442450945] Frame script registered
23:23:04 INFO - 1553901784909 Marionette DEBUG 3 <- [1,1,null,{"sessionId":"028aa20a-8411-4d9f-b164-0e5a569c2927","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... \Temp\\tmpdq1kwn.$¢€ἶA","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
23:23:04 INFO - TEST-PASS | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_named_profile_unicode_escape_characters | took 2557ms
23:23:04 INFO - 1553901784913 Marionette DEBUG 3 -> [0,2,"WebDriver:DeleteSession",{}]
23:23:04 INFO - 1553901784914 Marionette DEBUG 3 <- [1,2,null,{"value":null}]
23:23:04 INFO - 1553901784915 Marionette DEBUG Closed connection 3

Comment 1

[Intermittent Failures Robot]

1 failures in 3910 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=1540329&startday=2019-03-25&endday=2019-03-31&tree=all

Comment 2

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

Missing marionette-startup-requested observer notification, which means it depends on bug 1382162.

Comment 3

[Firefox Bug Husbandry Bot]

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

Comment 5

[BMO Automation]

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