Closed Bug 1458725 Opened 7 years ago Closed 7 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestServerQuitApplication.test_attempt_quit | IOError: Process killed after 120s because no connection to Marionette server could be established.

Categories

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

Version 3
defect

Tracking

(firefox61 wontfix, firefox63 fixed, firefox64 fixed)

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

People

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

References

Details

(Keywords: intermittent-failure)

Filed by: apavel [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=176646411&repo=autoland https://queue.taskcluster.net/v1/task/D6SoBRCwTi62lVq4uaTHVg/runs/0/artifacts/public/logs/live_backing.log [task 2018-05-02T22:30:27.537Z] 22:30:27 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestServerQuitApplication.test_attempt_quit [task 2018-05-02T22:30:27.539Z] 22:30:27 INFO - 1525300227537 Marionette DEBUG Closed connection 2 [task 2018-05-02T22:30:27.547Z] 22:30:27 INFO - 1525300227542 Marionette DEBUG Accepted connection 3 from 127.0.0.1:49584 [task 2018-05-02T22:30:27.556Z] 22:30:27 INFO - 1525300227550 Marionette TRACE 3 -> [0,1,"WebDriver:NewSession",{}] [task 2018-05-02T22:30:27.563Z] 22:30:27 INFO - 1525300227558 Marionette DEBUG Register listener.js for window 2147483649 [task 2018-05-02T22:30:27.572Z] 22:30:27 INFO - 1525300227565 Marionette TRACE 3 <- [1,1,null,{"sessionId":"4707b68e-3cc6-41a9-b42a-f02542a31729","capabilities":{"browserName":"firefox","browserVersion":"61.0a ... ssID":5335,"moz:profile":"/tmp/tmpFr9QFs.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}] [task 2018-05-02T22:30:27.572Z] 22:30:27 INFO - 1525300227568 Marionette TRACE 3 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}] [task 2018-05-02T22:30:27.574Z] 22:30:27 INFO - 1525300227569 Marionette TRACE 3 <- [1,2,null,{}] [task 2018-05-02T22:30:27.575Z] 22:30:27 INFO - 1525300227571 Marionette TRACE 3 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}] [task 2018-05-02T22:30:27.585Z] 22:30:27 INFO - 1525300227576 Marionette TRACE 3 <- [1,3,null,{}] [task 2018-05-02T22:30:27.587Z] 22:30:27 INFO - 1525300227578 Marionette TRACE 3 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}] [task 2018-05-02T22:30:27.588Z] 22:30:27 INFO - 1525300227579 Marionette TRACE 3 <- [1,4,null,{}] [task 2018-05-02T22:30:27.591Z] 22:30:27 INFO - 1525300227581 Marionette TRACE 3 -> [0,5,"quit",{"flags":["eAttemptQuit"]}] [task 2018-05-02T22:30:27.592Z] 22:30:27 INFO - 1525300227583 Marionette DEBUG New connections will no longer be accepted [task 2018-05-02T22:30:27.793Z] 22:30:27 INFO - 1525300227784 Marionette TRACE 3 <- [1,5,null,{"cause":"shutdown"}] [task 2018-05-02T22:30:27.811Z] 22:30:27 INFO - 1525300227803 Marionette DEBUG Closed connection 3 [task 2018-05-02T22:30:28.278Z] 22:30:28 INFO - *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping [task 2018-05-02T22:30:28.476Z] 22:30:28 INFO - 1525300228468 Marionette DEBUG Received observer notification xpcom-will-shutdown [task 2018-05-02T22:30:29.802Z] 22:30:29 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmpFr9QFs.mozrunner [task 2018-05-02T22:32:29.848Z] 22:32:29 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestServerQuitApplication.test_attempt_quit | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors [task 2018-05-02T22:32:29.848Z] 22:32:29 INFO - Traceback (most recent call last): [task 2018-05-02T22:32:29.849Z] 22:32:29 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 190, in run [task 2018-05-02T22:32:29.850Z] 22:32:29 INFO - self.tearDown() [task 2018-05-02T22:32:29.851Z] 22:32:29 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py", line 15, in tearDown [task 2018-05-02T22:32:29.852Z] 22:32:29 INFO - self.marionette.start_session() [task 2018-05-02T22:32:29.853Z] 22:32:29 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _ [task 2018-05-02T22:32:29.853Z] 22:32:29 INFO - return func(*args, **kwargs) [task 2018-05-02T22:32:29.854Z] 22:32:29 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1211, in start_session [task 2018-05-02T22:32:29.855Z] 22:32:29 INFO - self.start_binary(timeout) [task 2018-05-02T22:32:29.857Z] 22:32:29 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 640, in start_binary [task 2018-05-02T22:32:29.858Z] 22:32:29 INFO - reraise(IOError, msg.format(timeout), tb) [task 2018-05-02T22:32:29.859Z] 22:32:29 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 631, in start_binary [task 2018-05-02T22:32:29.860Z] 22:32:29 INFO - self.raise_for_port(timeout=timeout) [task 2018-05-02T22:32:29.861Z] 22:32:29 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-02T22:32:29.862Z] 22:32:29 INFO - self.host, self.port)) [task 2018-05-02T22:32:29.863Z] 22:32:29 INFO - TEST-INFO took 122314ms [task 2018-05-02T22:32:29.864Z] 22:32:29 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestServerQuitApplication.test_empty_default [task 2018-05-02T22:32:29.865Z] 22:32:29 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmpKkrnxE.mozrunner [task 2018-05-02T22:32:32.009Z] 22:32:32 INFO - 1525300352003 Marionette DEBUG Received observer notification profile-after-change [task 2018-05-02T22:32:32.167Z] 22:32:32 INFO - 1525300352155 Marionette DEBUG Received observer notification command-line-startup [task 2018-05-02T22:32:32.167Z] 22:32:32 INFO - 1525300352155 Marionette DEBUG Received observer notification nsPref:changed [task 2018-05-02T22:32:35.665Z] 22:32:35 INFO - 1525300355654 Marionette DEBUG Received observer notification sessionstore-windows-restored [task 2018-05-02T22:32:37.608Z] 22:32:37 INFO - 1525300357594 Marionette DEBUG New connections are accepted [task 2018-05-02T22:32:37.608Z] 22:32:37 INFO - 1525300357595 Marionette INFO Listening on port 2828 [task 2018-05-02T22:32:37.649Z] 22:32:37 INFO - 1525300357641 Marionette DEBUG Accepted connection 0 from 127.0.0.1:52198 [task 2018-05-02T22:32:37.665Z] 22:32:37 INFO - 1525300357661 Marionette DEBUG Accepted connection 1 from 127.0.0.1:52200 [task 2018-05-02T22:32:37.665Z] 22:32:37 INFO - 1525300357663 Marionette DEBUG Closed connection 0 [task 2018-05-02T22:32:37.698Z] 22:32:37 INFO - 1525300357686 Marionette TRACE 1 -> [0,1,"WebDriver:NewSession",{}] [task 2018-05-02T22:32:38.004Z] 22:32:38 INFO - 1525300358001 Marionette DEBUG Register listener.js for window 2147483649 [task 2018-05-02T22:32:38.045Z] 22:32:38 INFO - 1525300358041 Marionette TRACE 1 <- [1,1,null,{"sessionId":"3c4b3c71-0b7d-43e4-a3ef-857e055b297d","capabilities":{"browserName":"firefox","browserVersion":"61.0a ... ssID":5483,"moz:profile":"/tmp/tmpKkrnxE.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}] [task 2018-05-02T22:32:38.106Z] 22:32:38 INFO - 1525300358100 Marionette TRACE 1 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}] [task 2018-05-02T22:32:38.107Z] 22:32:38 INFO - 1525300358104 Marionette TRACE 1 <- [1,2,null,{}] [task 2018-05-02T22:32:38.124Z] 22:32:38 INFO - 1525300358119 Marionette TRACE 1 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}] [task 2018-05-02T22:32:38.125Z] 22:32:38 INFO - 1525300358122 Marionette TRACE 1 <- [1,3,null,{}] [task 2018-05-02T22:32:38.141Z] 22:32:38 INFO - 1525300358135 Marionette TRACE 1 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}] [task 2018-05-02T22:32:38.142Z] 22:32:38 INFO - 1525300358139 Marionette TRACE 1 <- [1,4,null,{}] [task 2018-05-02T22:32:38.160Z] 22:32:38 INFO - 1525300358156 Marionette TRACE 1 -> [0,5,"quit",{"flags":[]}] [task 2018-05-02T22:32:38.160Z] 22:32:38 INFO - 1525300358157 Marionette DEBUG New connections will no longer be accepted [task 2018-05-02T22:32:38.412Z] 22:32:38 INFO - 1525300358407 Marionette TRACE 1 <- [1,5,null,{"cause":"shutdown"}] [task 2018-05-02T22:32:38.440Z] 22:32:38 INFO - 1525300358435 Marionette DEBUG Closed connection 1 [task 2018-05-02T22:32:39.002Z] 22:32:39 INFO - JavaScript error: resource://gre/modules/JSONFile.jsm, line 159: Error: Data is not ready. [task 2018-05-02T22:32:39.003Z] 22:32:39 INFO - JavaScript error: resource://gre/modules/JSONFile.jsm, line 159: Error: Data is not ready. [task 2018-05-02T22:32:39.005Z] 22:32:39 INFO - JavaScript error: resource://gre/modules/JSONFile.jsm, line 159: Error: Data is not ready. [task 2018-05-02T22:32:39.182Z] 22:32:39 INFO - *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping [task 2018-05-02T22:32:39.364Z] 22:32:39 INFO - 1525300359360 Marionette DEBUG Received observer notification xpcom-will-shutdown [task 2018-05-02T22:32:40.747Z] 22:32:40 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmpKkrnxE.mozrunner [task 2018-05-02T22:32:41.843Z] 22:32:41 INFO - 1525300361838 Marionette DEBUG Received observer notification profile-after-change [task 2018-05-02T22:32:41.921Z] 22:32:41 INFO - 1525300361916 Marionette DEBUG Received observer notification command-line-startup [task 2018-05-02T22:32:41.921Z] 22:32:41 INFO - 1525300361917 Marionette DEBUG Received observer notification nsPref:changed [task 2018-05-02T22:32:43.617Z] 22:32:43 INFO - 1525300363606 Marionette DEBUG Received observer notification sessionstore-windows-restored [task 2018-05-02T22:32:45.585Z] 22:32:45 INFO - 1525300365573 Marionette DEBUG New connections are accepted [task 2018-05-02T22:32:45.587Z] 22:32:45 INFO - 1525300365575 Marionette INFO Listening on port 2828 [task 2018-05-02T22:32:45.609Z] 22:32:45 INFO - 1525300365605 Marionette DEBUG Accepted connection 0 from 127.0.0.1:52312 [task 2018-05-02T22:32:45.630Z] 22:32:45 INFO - 1525300365627 Marionette DEBUG Accepted connection 1 from 127.0.0.1:52314 [task 2018-05-02T22:32:45.638Z] 22:32:45 INFO - 1525300365632 Marionette DEBUG Closed connection 0 [task 2018-05-02T22:32:45.670Z] 22:32:45 INFO - 1525300365658 Marionette TRACE 1 -> [0,1,"WebDriver:NewSession",{}] [task 2018-05-02T22:32:45.969Z] 22:32:45 INFO - 1525300365958 Marionette DEBUG Register listener.js for window 2147483649 [task 2018-05-02T22:32:46.066Z] 22:32:46 INFO - 1525300366062 Marionette TRACE 1 <- [1,1,null,{"sessionId":"e9fd84d1-6307-459b-a2da-fd0d6f9243d3","capabilities":{"browserName":"firefox","browserVersion":"61.0a ... ssID":5606,"moz:profile":"/tmp/tmpKkrnxE.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}] [task 2018-05-02T22:32:46.090Z] 22:32:46 INFO - 1525300366087 Marionette TRACE 1 -> [0,2,"WebDriver:DeleteSession",{}] [task 2018-05-02T22:32:46.108Z] 22:32:46 INFO - TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestServerQuitApplication.test_empty_default | took 16253ms
Complete hang during startup of Firefox.
Depends on: 1414495
All recent failures are start-up hangs of Linux64 ASAN builds. It needs a fix on bug 1487243.
Depends on: 1487243
This failure should be fixed now with the patch on bug 1495404 for both central and beta, given that it was ASAN only related.
Assignee: nobody → stransky
Status: NEW → RESOLVED
Closed: 7 years ago
No longer depends on: 1414495
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.