Closed
Bug 1472853
Opened 6 years ago
Closed 6 years ago
Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_quit_with_dismissed_beforeunload_prompt | IOError: Process killed because a requested application quit did not happen within 120s
Categories
(Testing :: Marionette Client and Harness, defect, P5)
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=186055396&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/ElczWnDtSFuNA8sT02knTA/runs/0/artifacts/public/logs/live_backing.log [task 2018-07-02T22:02:41.982Z] 22:02:41 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_quit_with_dismissed_beforeunload_prompt [task 2018-07-02T22:02:41.983Z] 22:02:41 INFO - 1530568961975 Marionette TRACE 2 <- [1,18,null,{"value":null}] [task 2018-07-02T22:02:41.987Z] 22:02:41 INFO - 1530568961985 Marionette DEBUG Closed connection 2 [task 2018-07-02T22:02:41.995Z] 22:02:41 INFO - 1530568961990 Marionette DEBUG Accepted connection 3 from 127.0.0.1:33126 [task 2018-07-02T22:02:41.995Z] 22:02:41 INFO - 1530568961992 Marionette TRACE 3 -> [0,1,"WebDriver:NewSession",{}] [task 2018-07-02T22:02:42.014Z] 22:02:42 INFO - 1530568962002 Marionette DEBUG [2147483649] Frame script loaded [task 2018-07-02T22:02:42.014Z] 22:02:42 INFO - 1530568962006 Marionette DEBUG [2147483649] Frame script registered [task 2018-07-02T22:02:42.014Z] 22:02:42 INFO - 1530568962010 Marionette TRACE 3 <- [1,1,null,{"sessionId":"34bcd12b-b15c-46bc-bd9f-fafe7675d5dc","capabilities":{"browserName":"firefox","browserVersion":"63.0a ... ssID":5841,"moz:profile":"/tmp/tmpiF40Sn.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}] [task 2018-07-02T22:02:42.022Z] 22:02:42 INFO - 1530568962016 Marionette TRACE 3 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}] [task 2018-07-02T22:02:42.022Z] 22:02:42 INFO - 1530568962017 Marionette TRACE 3 <- [1,2,null,{"value":null}] [task 2018-07-02T22:02:42.022Z] 22:02:42 INFO - 1530568962019 Marionette TRACE 3 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}] [task 2018-07-02T22:02:42.025Z] 22:02:42 INFO - 1530568962022 Marionette TRACE 3 <- [1,3,null,{"value":null}] [task 2018-07-02T22:02:42.029Z] 22:02:42 INFO - 1530568962024 Marionette TRACE 3 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}] [task 2018-07-02T22:02:42.030Z] 22:02:42 INFO - 1530568962027 Marionette TRACE 3 <- [1,4,null,{"value":null}] [task 2018-07-02T22:02:42.033Z] 22:02:42 INFO - 1530568962030 Marionette TRACE 3 -> [0,5,"Marionette:GetContext",{}] [task 2018-07-02T22:02:42.033Z] 22:02:42 INFO - 1530568962032 Marionette TRACE 3 <- [1,5,null,{"value":"content"}] [task 2018-07-02T22:02:42.041Z] 22:02:42 INFO - 1530568962038 Marionette TRACE 3 -> [0,6,"Marionette:SetContext",{"value":"chrome"}] [task 2018-07-02T22:02:42.041Z] 22:02:42 INFO - 1530568962039 Marionette TRACE 3 <- [1,6,null,{"value":null}] [task 2018-07-02T22:02:42.045Z] 22:02:42 INFO - 1530568962042 Marionette TRACE 3 -> [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":895}] [task 2018-07-02T22:02:42.053Z] 22:02:42 INFO - 1530568962051 Marionette TRACE 3 <- [1,7,null,{"value":""}] [task 2018-07-02T22:02:42.057Z] 22:02:42 INFO - 1530568962054 Marionette TRACE 3 -> [0,8,"Marionette:SetContext",{"value":"content"}] [task 2018-07-02T22:02:42.057Z] 22:02:42 INFO - 1530568962055 Marionette TRACE 3 <- [1,8,null,{"value":null}] [task 2018-07-02T22:02:42.061Z] 22:02:42 INFO - 1530568962058 Marionette TRACE 3 -> [0,9,"Marionette:GetContext",{}] [task 2018-07-02T22:02:42.061Z] 22:02:42 INFO - 1530568962059 Marionette TRACE 3 <- [1,9,null,{"value":"content"}] [task 2018-07-02T22:02:42.064Z] 22:02:42 INFO - 1530568962062 Marionette TRACE 3 -> [0,10,"Marionette:SetContext",{"value":"chrome"}] [task 2018-07-02T22:02:42.064Z] 22:02:42 INFO - 1530568962063 Marionette TRACE 3 <- [1,10,null,{"value":null}] [task 2018-07-02T22:02:42.081Z] 22:02:42 INFO - 1530568962068 Marionette TRACE 3 -> [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":929}] [task 2018-07-02T22:02:42.081Z] 22:02:42 INFO - 1530568962076 Marionette TRACE 3 <- [1,11,null,{"value":null}] [task 2018-07-02T22:02:42.082Z] 22:02:42 INFO - 1530568962078 Marionette TRACE 3 -> [0,12,"Marionette:SetContext",{"value":"content"}] [task 2018-07-02T22:02:42.082Z] 22:02:42 INFO - 1530568962079 Marionette TRACE 3 <- [1,12,null,{"value":null}] [task 2018-07-02T22:02:42.090Z] 22:02:42 INFO - 1530568962084 Marionette TRACE 3 -> [0,13,"WebDriver:Navigate",{"url":"data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cinput%20type%3D%22text%22 ... B%0A%20%20%20%20%20%20%20%20%20%20%20%20%7D%29%3B%0A%20%20%20%20%20%20%20%20%20%20%3C/script%3E%0A%20%20%20%20%20%20%20%20"}] [task 2018-07-02T22:02:42.118Z] 22:02:42 INFO - 1530568962110 Marionette DEBUG [2147483649] Received DOM event beforeunload for about:blank [task 2018-07-02T22:02:42.154Z] 22:02:42 INFO - 1530568962142 Marionette DEBUG [2147483649] Received DOM event pagehide for about:blank [task 2018-07-02T22:02:42.291Z] 22:02:42 INFO - 1530568962280 Marionette DEBUG [2147483649] Received DOM event DOMContentLoaded for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cinput%20type%3D%22text%22%3E%0A%20%20%20%20%20%20%20%20%20%2 ... 9%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%7D%29%3B%0A%20%20%20%20%20%20%20%20%20%20%3C/script%3E%0A%20%20%20%20%20%20%20%20 [task 2018-07-02T22:02:42.411Z] 22:02:42 INFO - 1530568962404 Marionette DEBUG [2147483649] Received DOM event pageshow for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%3Cinput%20type%3D%22text%22%3E%0A%20%20%20%20%20%20%20%20%20%2 ... 9%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%7D%29%3B%0A%20%20%20%20%20%20%20%20%20%20%3C/script%3E%0A%20%20%20%20%20%20%20%20 [task 2018-07-02T22:02:42.428Z] 22:02:42 INFO - 1530568962422 Marionette TRACE 3 <- [1,13,null,{"value":null}] [task 2018-07-02T22:02:42.489Z] 22:02:42 INFO - 1530568962475 Marionette TRACE 3 -> [0,14,"WebDriver:FindElement",{"using":"tag name","value":"input"}] [task 2018-07-02T22:02:42.506Z] 22:02:42 INFO - 1530568962502 Marionette TRACE 3 <- [1,14,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"153342c3-15e1-4500-b80d-98ee6e207356","ELEMENT":"153342c3-15e1-4500-b80d-98ee6e207356"}}] [task 2018-07-02T22:02:42.514Z] 22:02:42 INFO - 1530568962511 Marionette TRACE 3 -> [0,15,"WebDriver:ElementSendKeys",{"text":"foo","id":"153342c3-15e1-4500-b80d-98ee6e207356"}] [task 2018-07-02T22:02:42.578Z] 22:02:42 INFO - 1530568962576 Marionette TRACE 3 <- [1,15,null,{"value":null}] [task 2018-07-02T22:02:42.586Z] 22:02:42 INFO - 1530568962581 Marionette TRACE 3 -> [0,16,"Marionette:GetContext",{}] [task 2018-07-02T22:02:42.586Z] 22:02:42 INFO - 1530568962583 Marionette TRACE 3 <- [1,16,null,{"value":"content"}] [task 2018-07-02T22:02:42.603Z] 22:02:42 INFO - 1530568962598 Marionette TRACE 3 -> [0,17,"Marionette:SetContext",{"value":"chrome"}] [task 2018-07-02T22:02:42.604Z] 22:02:42 INFO - 1530568962601 Marionette TRACE 3 <- [1,17,null,{"value":null}] [task 2018-07-02T22:02:42.781Z] 22:02:42 INFO - 1530568962771 Marionette TRACE 3 -> [0,18,"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":1064}] [task 2018-07-02T22:02:42.810Z] 22:02:42 INFO - 1530568962804 Marionette TRACE 3 <- [1,18,null,{"value":false}] [task 2018-07-02T22:02:42.831Z] 22:02:42 INFO - 1530568962824 Marionette TRACE 3 -> [0,19,"Marionette:SetContext",{"value":"content"}] [task 2018-07-02T22:02:42.831Z] 22:02:42 INFO - 1530568962826 Marionette TRACE 3 <- [1,19,null,{"value":null}] [task 2018-07-02T22:02:42.847Z] 22:02:42 INFO - 1530568962836 Marionette TRACE 3 -> [0,20,"Marionette:Quit",{"flags":["eForceQuit"]}] [task 2018-07-02T22:02:42.847Z] 22:02:42 INFO - 1530568962838 Marionette INFO Stopped listening on port 2828 [task 2018-07-02T22:02:43.048Z] 22:02:43 INFO - 1530568963040 Marionette TRACE 3 <- [1,20,null,{"cause":"shutdown"}] [task 2018-07-02T22:02:43.186Z] 22:02:43 INFO - 1530568963179 Marionette DEBUG Closed connection 3 [task 2018-07-02T22:02:43.263Z] 22:02:43 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D00FF,name=PContent::Msg_AccumulateChildHistograms) Closed channel: cannot send/recv [task 2018-07-02T22:02:43.264Z] 22:02:43 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D0100,name=PContent::Msg_AccumulateChildKeyedHistograms) Closed channel: cannot send/recv [task 2018-07-02T22:02:43.264Z] 22:02:43 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x2D0104,name=PContent::Msg_RecordDiscardedData) Closed channel: cannot send/recv [task 2018-07-02T22:02:43.953Z] 22:02:43 INFO - 1530568963951 Marionette DEBUG Received observer notification xpcom-will-shutdown [task 2018-07-02T22:02:43.956Z] 22:02:43 INFO - 1530568963953 Marionette DEBUG Remote service is inactive [task 2018-07-02T22:04:44.209Z] 22:04:44 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_quit_with_dismissed_beforeunload_prompt | IOError: Process killed because a requested application quit did not happen within 120s. Check gecko.log for errors. [task 2018-07-02T22:04:44.210Z] 22:04:44 INFO - Traceback (most recent call last): [task 2018-07-02T22:04:44.211Z] 22:04:44 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run [task 2018-07-02T22:04:44.212Z] 22:04:44 INFO - testMethod() [task 2018-07-02T22:04:44.213Z] 22:04:44 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py", line 294, in test_in_app_quit_with_dismissed_beforeunload_prompt [task 2018-07-02T22:04:44.216Z] 22:04:44 INFO - self.marionette.quit(in_app=True) [task 2018-07-02T22:04:44.216Z] 22:04:44 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _ [task 2018-07-02T22:04:44.216Z] 22:04:44 INFO - return func(*args, **kwargs) [task 2018-07-02T22:04:44.217Z] 22:04:44 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1119, in quit [task 2018-07-02T22:04:44.218Z] 22:04:44 INFO - raise IOError(message.format(self.DEFAULT_SHUTDOWN_TIMEOUT)) [task 2018-07-02T22:04:44.218Z] 22:04:44 INFO - TEST-INFO took 122227ms [task 2018-07-02T22:04:44.219Z] 22:04:44 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmpybojFW.mozrunner [task 2018-07-02T22:04:44.292Z] 22:04:44 INFO - *** You are running in headless mode. [task 2018-07-02T22:04:46.058Z] 22:04:46 INFO - 1530569086051 Marionette DEBUG Received observer notification profile-after-change [task 2018-07-02T22:04:46.182Z] 22:04:46 INFO - 1530569086179 Marionette DEBUG Received observer notification command-line-startup [task 2018-07-02T22:04:46.182Z] 22:04:46 INFO - 1530569086180 Marionette DEBUG Received observer notification nsPref:changed [task 2018-07-02T22:04:46.183Z] 22:04:46 INFO - 1530569086180 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false) [task 2018-07-02T22:04:49.251Z] 22:04:49 INFO - 1530569089242 Marionette DEBUG Received observer notification sessionstore-windows-restored [task 2018-07-02T22:04:49.253Z] 22:04:49 INFO - 1530569089242 Marionette DEBUG Waiting for delayed startup... [task 2018-07-02T22:04:51.291Z] 22:04:51 INFO - 1530569091286 Marionette DEBUG Waiting for startup tests... [task 2018-07-02T22:04:51.481Z] 22:04:51 INFO - 1530569091476 Marionette INFO Listening on port 2828 [task 2018-07-02T22:04:51.483Z] 22:04:51 INFO - 1530569091479 Marionette DEBUG Remote service is active [task 2018-07-02T22:04:51.600Z] 22:04:51 INFO - 1530569091590 Marionette DEBUG Accepted connection 0 from 127.0.0.1:33352 [task 2018-07-02T22:04:51.603Z] 22:04:51 INFO - 1530569091597 Marionette DEBUG Closed connection 0 [task 2018-07-02T22:04:51.608Z] 22:04:51 INFO - 1530569091605 Marionette DEBUG Accepted connection 1 from 127.0.0.1:33354 [task 2018-07-02T22:04:51.626Z] 22:04:51 INFO - 1530569091618 Marionette TRACE 1 -> [0,1,"WebDriver:NewSession",{}] [task 2018-07-02T22:04:51.909Z] 22:04:51 INFO - 1530569091905 Marionette DEBUG [2147483649] Frame script loaded [task 2018-07-02T22:04:51.917Z] 22:04:51 INFO - 1530569091912 Marionette DEBUG [2147483649] Frame script registered [task 2018-07-02T22:04:51.938Z] 22:04:51 INFO - 1530569091932 Marionette TRACE 1 <- [1,1,null,{"sessionId":"d6b24902-05e7-4901-9fcb-21335edd8f12","capabilities":{"browserName":"firefox","browserVersion":"63.0a ... ssID":5954,"moz:profile":"/tmp/tmpybojFW.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}] [task 2018-07-02T22:04:51.955Z] 22:04:51 INFO - 1530569091946 Marionette TRACE 1 -> [0,2,"Marionette:GetContext",{}] [task 2018-07-02T22:04:51.955Z] 22:04:51 INFO - 1530569091948 Marionette TRACE 1 <- [1,2,null,{"value":"content"}] [task 2018-07-02T22:04:51.955Z] 22:04:51 INFO - 1530569091951 Marionette TRACE 1 -> [0,3,"Marionette:SetContext",{"value":"chrome"}] [task 2018-07-02T22:04:51.955Z] 22:04:51 INFO - 1530569091952 Marionette TRACE 1 <- [1,3,null,{"value":null}] [task 2018-07-02T22:04:51.964Z] 22:04:51 INFO - 1530569091957 Marionette TRACE 1 -> [0,4,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":["startup.homepage_welcome_url"],"filename":".. ... resource://gre/modules/Preferences.jsm\");\n Preferences.reset(arguments[0]);","sandbox":"default","line":867}] [task 2018-07-02T22:04:51.969Z] 22:04:51 INFO - 1530569091966 Marionette TRACE 1 <- [1,4,null,{"value":null}] [task 2018-07-02T22:04:51.973Z] 22:04:51 INFO - 1530569091969 Marionette TRACE 1 -> [0,5,"Marionette:SetContext",{"value":"content"}] [task 2018-07-02T22:04:51.973Z] 22:04:51 INFO - 1530569091971 Marionette TRACE 1 <- [1,5,null,{"value":null}] [task 2018-07-02T22:04:52.021Z] 22:04:52 INFO - 1530569092019 Marionette TRACE 1 -> [0,6,"WebDriver:DeleteSession",{}] [task 2018-07-02T22:04:52.032Z] 22:04:52 INFO - 1530569092025 Marionette TRACE 1 <- [1,6,null,{"value":null}]
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 4•6 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
|
||
Comment 5•6 years ago
|
||
This is still happening. Recent failure: https://treeherder.mozilla.org/logviewer.html#?job_id=204263880&repo=mozilla-beta&lineNumber=34698 [task 2018-10-09T16:51:11.813Z] 16:51:11 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x300117,name=PContent::Msg_AsyncMessage) Channel closing: too late to send/recv, messages will be lost [task 2018-10-09T16:51:11.814Z] 16:51:11 INFO - JavaScript error: resource://gre/modules/GCTelemetry.jsm, line 231: NS_ERROR_UNEXPECTED: [task 2018-10-09T16:51:11.815Z] 16:51:11 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x3000BB,name=PContent::Msg_ScriptError) Channel closing: too late to send/recv, messages will be lost [task 2018-10-09T16:51:12.740Z] 16:51:12 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x300117,name=PContent::Msg_AsyncMessage) Channel closing: too late to send/recv, messages will be lost [task 2018-10-09T16:51:12.741Z] 16:51:12 INFO - JavaScript error: resource://gre/modules/GCTelemetry.jsm, line 231: NS_ERROR_UNEXPECTED: [task 2018-10-09T16:51:12.742Z] 16:51:12 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x3000BB,name=PContent::Msg_ScriptError) Channel closing: too late to send/recv, messages will be lost [task 2018-10-09T16:51:13.736Z] 16:51:13 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x300105,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-10-09T16:51:13.737Z] 16:51:13 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x300106,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-10-09T16:51:13.738Z] 16:51:13 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x30010A,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost [task 2018-10-09T16:51:14.692Z] 16:51:14 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x300105,name=PContent::Msg_AccumulateChildHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-10-09T16:51:14.694Z] 16:51:14 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x300106,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost [task 2018-10-09T16:51:14.694Z] 16:51:14 INFO - ###!!! [Child][MessageChannel] Error: (msgtype=0x30010A,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost [task 2018-10-09T16:52:05.077Z] 16:52:05 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_quit_with_dismissed_beforeunload_prompt | IOError: Process killed because a requested application quit did not happen within 120s. Check gecko.log for errors. [task 2018-10-09T16:52:05.077Z] 16:52:05 INFO - Traceback (most recent call last): [task 2018-10-09T16:52:05.077Z] 16:52:05 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run [task 2018-10-09T16:52:05.077Z] 16:52:05 INFO - testMethod() [task 2018-10-09T16:52:05.077Z] 16:52:05 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py", line 294, in test_in_app_quit_with_dismissed_beforeunload_prompt [task 2018-10-09T16:52:05.080Z] 16:52:05 INFO - self.marionette.quit(in_app=True) [task 2018-10-09T16:52:05.082Z] 16:52:05 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _ [task 2018-10-09T16:52:05.083Z] 16:52:05 INFO - return func(*args, **kwargs) [task 2018-10-09T16:52:05.085Z] 16:52:05 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1113, in quit [task 2018-10-09T16:52:05.085Z] 16:52:05 INFO - raise IOError(message.format(self.DEFAULT_SHUTDOWN_TIMEOUT)) [task 2018-10-09T16:52:05.086Z] 16:52:05 INFO - TEST-INFO took 122206ms
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
| Comment hidden (Intermittent Failures Robot) |
|
Assignee | |
Comment 7•6 years ago
|
||
The real underlying reason here is a hang of Firefox during shutdown. After the `xpcom-will-shutdown` notification there are a lot of Message channel errors for GC telemetry. Maybe this is keeping the process active? But I wonder why the background monitor doesn't actually kill the process. Andrew, do you have an idea or is that problem already known?
Flags: needinfo?(continuation)
|
|
Assignee | |
Comment 8•6 years ago
|
||
See the following link for details: https://treeherder.mozilla.org/logviewer.html#?job_id=204491941&repo=mozilla-inbound&lineNumber=34694-34759
|
||
Comment 9•6 years ago
|
||
The channel errors always happen. Anything that tries to send messages late just needs to deal with it. The basic problem here is that in non-leak checking builds we kill the child process if it takes too long to shut down, but in leak checking builds we don't, because we have to run a bunch of shutdown stuff to figure out if there are leaks. We run a number of GCs and CCs, and LSan itself has to do some kind of analysis of leaks. If this is only happening rarely, and in fact the child is being killed after a minute or two rather than just lingering for a really long time (which I think was a problem before) then I'm not sure there's anything to do here.
Flags: needinfo?(continuation)
|
|
Assignee | |
Comment 10•6 years ago
|
||
(In reply to Andrew McCreight [:mccr8] from comment #9) > process if it takes too long to shut down, but in leak checking builds we > don't, because we have to run a bunch of shutdown stuff to figure out if > there are leaks. We run a number of GCs and CCs, and LSan itself has to do > some kind of analysis of leaks. > > If this is only happening rarely, and in fact the child is being killed > after a minute or two rather than just lingering for a really long time Oh, that would explain why we kill Firefox. Marionette itself only waits 70s at the moment during shutdown of Firefox, and that for any kind of build. If ASAN builds can take longer for shutdown, Marionette should also wait longer. I assume it would be similar to bug 1443922 for geckodriver, where we want to use the timeout as given by the preference `toolkit.asyncshutdown.crash_timeout`?
Flags: needinfo?(continuation)
|
|
Assignee | |
Comment 12•6 years ago
|
||
With the fix on bug 1500242 landed, we shouldn't see this specific failure message anymore.
Assignee: nobody → hskupin
Status: REOPENED → RESOLVED
Closed: 6 years ago → 6 years ago
status-firefox64:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla64
|
||
Updated•1 year ago
|
Product: Testing → Remote Protocol
|
|
||
Comment 13•1 year ago
|
||
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.
Description
•