Closed Bug 1591344 Opened 6 years ago Closed 5 years ago

Intermittent dom/ipc/tests/browser_ElapsedTime.js | Test timed out -

Categories

(Core :: DOM: Content Processes, defect, P5)

defect

Tracking

()

RESOLVED INVALID

People

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

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell disabled])

Attachments

(2 files)

Filed by: ccoroiu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=272910784&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/AuvBTqhjTkmqOuZ8aG_61g/runs/0/artifacts/public/logs/live_backing.log


task 2019-10-25T07:50:43.790Z] 07:50:43 INFO - TEST-START | dom/ipc/tests/browser_ElapsedTime.js
[task 2019-10-25T07:52:13.888Z] 07:52:13 INFO - TEST-INFO | started process screenshot
[task 2019-10-25T07:52:14.120Z] 07:52:14 INFO - TEST-INFO | screenshot: exit 0
[task 2019-10-25T07:52:14.121Z] 07:52:14 INFO - Buffered messages logged at 07:50:43
[task 2019-10-25T07:52:14.121Z] 07:52:14 INFO - Entering test bound testLongElapsedTime
[task 2019-10-25T07:52:14.122Z] 07:52:14 INFO - Buffered messages logged at 07:50:44
[task 2019-10-25T07:52:14.122Z] 07:52:14 INFO - Console message: [JavaScript Error: "RemoteWebProgress failed to call onStateChange: [Exception... "Component does not have requested interface [nsIWebProgressListener.onStateChange]" nsresult: "0x80004002 (NS_NOINTERFACE)" location: "JS frame :: resource://gre/modules/RemoteWebProgress.jsm :: _callProgressListeners :: line 75" data: no]
[task 2019-10-25T07:52:14.123Z] 07:52:14 INFO - " {file: "resource://gre/modules/RemoteWebProgress.jsm" line: 77}]
[task 2019-10-25T07:52:14.123Z] 07:52:14 INFO - _callProgressListeners@resource://gre/modules/RemoteWebProgress.jsm:77:14
[task 2019-10-25T07:52:14.123Z] 07:52:14 INFO - onStateChange@resource://gre/modules/RemoteWebProgress.jsm:86:10
[task 2019-10-25T07:52:14.123Z] 07:52:14 INFO -
[task 2019-10-25T07:52:14.124Z] 07:52:14 INFO - Buffered messages logged at 07:50:45
[task 2019-10-25T07:52:14.124Z] 07:52:14 INFO - Console message: [JavaScript Error: "RemoteWebProgress failed to call onStateChange: [Exception... "Component does not have requested interface [nsIWebProgressListener.onStateChange]" nsresult: "0x80004002 (NS_NOINTERFACE)" location: "JS frame :: resource://gre/modules/RemoteWebProgress.jsm :: _callProgressListeners :: line 75" data: no]
[task 2019-10-25T07:52:14.124Z] 07:52:14 INFO - " {file: "resource://gre/modules/RemoteWebProgress.jsm" line: 77}]
[task 2019-10-25T07:52:14.124Z] 07:52:14 INFO - _callProgressListeners@resource://gre/modules/RemoteWebProgress.jsm:77:14
[task 2019-10-25T07:52:14.124Z] 07:52:14 INFO - onStateChange@resource://gre/modules/RemoteWebProgress.jsm:86:10
[task 2019-10-25T07:52:14.124Z] 07:52:14 INFO -
[task 2019-10-25T07:52:14.125Z] 07:52:14 INFO - Buffered messages finished
[task 2019-10-25T07:52:14.125Z] 07:52:14 INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_ElapsedTime.js | Test timed out -
[task 2019-10-25T07:52:14.125Z] 07:52:14 INFO - GECKO(7276) | MEMORY STAT heapAllocated not supported in this build configuration.
[task 2019-10-25T07:52:14.125Z] 07:52:14 INFO - GECKO(7276) | MEMORY STAT | vsize 19406099MB | vsizeMaxContiguous 67498882MB | residentFast 935MB
[task 2019-10-25T07:52:14.125Z] 07:52:14 INFO - TEST-OK | dom/ipc/tests/browser_ElapsedTime.js | took 90217ms
[task 2019-10-25T07:52:14.125Z] 07:52:14 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-25T07:52:14.126Z] 07:52:14 INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_ElapsedTime.js | Found a tab after previous test timed out: https://example.com/browser/dom/ipc/tests/elapsed_time.sjs -
[task 2019-10-25T07:52:14.126Z] 07:52:14 INFO - checking window state
[task 2019-10-25T07:52:14.144Z] 07:52:14 INFO - TEST-START | dom/ipc/tests/browser_cancel_content_js.js
[task 2019-10-25T07:52:15.424Z] 07:52:15 INFO - GECKO(7276) | JavaScript warning: http://mochi.test:8888/browser/dom/ipc/tests/file_cancel_content_js.html, line 15: Error: Script terminated by timeout at:
[task 2019-10-25T07:52:15.424Z] 07:52:15 INFO - GECKO(7276) | @http://mochi.test:8888/browser/dom/ipc/tests/file_cancel_content_js.html:15:14
[task 2019-10-25T07:52:19.146Z] 07:52:19 INFO - GECKO(7276) | MEMORY STAT | vsize 19406125MB | vsizeMaxContiguous 67498882MB | residentFast 947MB

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

This has 27 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-04-11&endday=2020-04-18&tree=trunk&bug=1591344
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=298122515&repo=autoland
It mostly fails on windows10-64 asan. Neha, could you please assign this to someone to take a look? Thank you.

[task 2020-04-17T17:16:28.786Z] 17:16:28     INFO - Application command: Z:\task_1587140640\build\application\firefox\firefox.exe -marionette --wait-for-browser -foreground -profile c:\users\task_1587140640\appdata\local\temp\tmpz0ss_g.mozrunner
[task 2020-04-17T17:16:28.786Z] 17:16:28     INFO - runtests.py | Application pid: 6448
[task 2020-04-17T17:16:28.786Z] 17:16:28     INFO - TEST-INFO | started process GECKO(6448)
[task 2020-04-17T17:16:29.721Z] 17:16:29     INFO - GECKO(6448) | defineSharedArrayBufferConstructor: 1
[task 2020-04-17T17:16:30.821Z] 17:16:30     INFO - GECKO(6448) | 1587143790818	Marionette	TRACE	Marionette enabled
[task 2020-04-17T17:16:31.082Z] 17:16:31     INFO - GECKO(6448) | 1587143791070	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-04-17T17:16:33.488Z] 17:16:33     INFO - GECKO(6448) | defineSharedArrayBufferConstructor: 1
[task 2020-04-17T17:16:34.445Z] 17:16:34     INFO - GECKO(6448) | defineSharedArrayBufferConstructor: 1
[task 2020-04-17T17:16:34.952Z] 17:16:34     INFO - GECKO(6448) | defineSharedArrayBufferConstructor: 1
[task 2020-04-17T17:16:36.856Z] 17:16:36     INFO - GECKO(6448) | 1587143796846	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2020-04-17T17:16:36.856Z] 17:16:36     INFO - GECKO(6448) | 1587143796846	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2020-04-17T17:16:36.998Z] 17:16:36     INFO - GECKO(6448) | 1587143796992	Marionette	TRACE	All scripts recorded.
[task 2020-04-17T17:16:37.199Z] 17:16:37     INFO - GECKO(6448) | 1587143797193	Marionette	INFO	Listening on port 2828
[task 2020-04-17T17:16:37.199Z] 17:16:37     INFO - GECKO(6448) | 1587143797194	Marionette	DEBUG	Marionette is listening
[task 2020-04-17T17:16:37.218Z] 17:16:37     INFO - GECKO(6448) | 1587143797208	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:51520
[task 2020-04-17T17:16:37.218Z] 17:16:37     INFO - GECKO(6448) | 1587143797215	Marionette	DEBUG	Closed connection 0
[task 2020-04-17T17:16:37.218Z] 17:16:37     INFO - GECKO(6448) | 1587143797216	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:51521
[task 2020-04-17T17:16:37.223Z] 17:16:37     INFO - GECKO(6448) | 1587143797220	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-04-17T17:16:37.322Z] 17:16:37     INFO - GECKO(6448) | 1587143797312	Marionette	TRACE	[20] Frame script loaded
[task 2020-04-17T17:16:37.322Z] 17:16:37     INFO - GECKO(6448) | 1587143797317	Marionette	TRACE	[20] Frame script registered
[task 2020-04-17T17:16:37.371Z] 17:16:37     INFO - GECKO(6448) | 1587143797365	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"deec79eb-1c78-48b7-8c56-9f1d32ae27fd","capabilities":{"browserName":"firefox","browserVersion":"77.0a ... \\tmpz0ss_g.mozrunner","moz:shutdownTimeout":180000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-04-17T17:16:37.409Z] 17:16:37     INFO - GECKO(6448) | 1587143797398	Marionette	DEBUG	1 -> [0,2,"Addon:Install",{"path":"c:\\users\\task_1587140640\\appdata\\local\\temp\\tmpdc_vja.zip","temporary":false}]
[task 2020-04-17T17:16:37.500Z] 17:16:37     INFO - GECKO(6448) | 1587143797494	Marionette	TRACE	[26] Frame script loaded
[task 2020-04-17T17:16:37.500Z] 17:16:37     INFO - GECKO(6448) | 1587143797496	Marionette	TRACE	[26] Frame script registered
[task 2020-04-17T17:16:39.906Z] 17:16:39     INFO - GECKO(6448) | 1587143799899	Marionette	DEBUG	1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2020-04-17T17:16:39.928Z] 17:16:39     INFO - GECKO(6448) | 1587143799926	Marionette	DEBUG	1 -> [0,3,"Addon:Install",{"path":"c:\\users\\task_1587140640\\appdata\\local\\temp\\tmpmbso6x.zip","temporary":false}]
[task 2020-04-17T17:16:40.013Z] 17:16:40     INFO - GECKO(6448) | 1587143800010	Marionette	DEBUG	1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2020-04-17T17:16:40.018Z] 17:16:40     INFO - GECKO(6448) | 1587143800015	Marionette	DEBUG	1 -> [0,4,"Marionette:GetContext",{}]
[task 2020-04-17T17:16:40.018Z] 17:16:40     INFO - GECKO(6448) | 1587143800016	Marionette	DEBUG	1 <- [1,4,null,{"value":"content"}]
[task 2020-04-17T17:16:40.020Z] 17:16:40     INFO - GECKO(6448) | 1587143800018	Marionette	DEBUG	1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-04-17T17:16:40.020Z] 17:16:40     INFO - GECKO(6448) | 1587143800019	Marionette	DEBUG	1 <- [1,5,null,{"value":null}]
[task 2020-04-17T17:16:40.025Z] 17:16:40     INFO - GECKO(6448) | 1587143800022	Marionette	DEBUG	1 -> [0,6,"WebDriver:ExecuteScript",{"script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, ... ":"browser-chrome"}],"filename":"Z:\\task_1587140640\\build\\tests\\mochitest\\runtests.py","sandbox":"default","line":1790}]
[task 2020-04-17T17:16:40.065Z] 17:16:40     INFO - GECKO(6448) | 1587143800055	Marionette	DEBUG	1 <- [1,6,null,{"value":null}]
[task 2020-04-17T17:16:40.105Z] 17:16:40     INFO - GECKO(6448) | 1587143800103	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-04-17T17:16:40.254Z] 17:16:40     INFO - GECKO(6448) | 1587143800248	Marionette	DEBUG	1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2020-04-17T17:16:40.254Z] 17:16:40     INFO - GECKO(6448) | 1587143800249	Marionette	DEBUG	1 <- [1,7,null,{"value":null}]
[task 2020-04-17T17:16:40.264Z] 17:16:40     INFO - GECKO(6448) | 1587143800256	Marionette	DEBUG	1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2020-04-17T17:16:40.264Z] 17:16:40     INFO - GECKO(6448) | 1587143800259	Marionette	DEBUG	1 <- [1,8,null,{"value":null}]
[task 2020-04-17T17:16:40.266Z] 17:16:40     INFO - runtests.py | Waiting for browser...
[task 2020-04-17T17:16:40.271Z] 17:16:40     INFO - GECKO(6448) | 1587143800267	Marionette	DEBUG	Closed connection 1
[task 2020-04-17T17:16:40.597Z] 17:16:40     INFO - *** Start BrowserChrome Test Results ***
[task 2020-04-17T17:16:40.668Z] 17:16:40     INFO - checking window state
[task 2020-04-17T17:16:40.712Z] 17:16:40     INFO - TEST-START | dom/ipc/tests/browser_ElapsedTime.js
[task 2020-04-17T17:18:10.788Z] 17:18:10     INFO - TEST-INFO | started process screenshot
[task 2020-04-17T17:18:10.990Z] 17:18:10     INFO - TEST-INFO | screenshot: exit 0
[task 2020-04-17T17:18:10.990Z] 17:18:10     INFO - Buffered messages logged at 17:16:40
[task 2020-04-17T17:18:10.990Z] 17:18:10     INFO - Entering test bound testLongElapsedTime
[task 2020-04-17T17:18:10.990Z] 17:18:10     INFO - Buffered messages logged at 17:16:41
[task 2020-04-17T17:18:10.990Z] 17:18:10     INFO - Console message: [JavaScript Error: "RemoteWebProgress failed to call onStateChange: [Exception... "Component does not have requested interface [nsIWebProgressListener.onStateChange]"  nsresult: "0x80004002 (NS_NOINTERFACE)"  location: "JS frame :: resource://gre/modules/RemoteWebProgress.jsm :: _callProgressListeners :: line 75"  data: no]" {file: "resource://gre/modules/RemoteWebProgress.jsm" line: 78}]
[task 2020-04-17T17:18:10.990Z] 17:18:10     INFO - _callProgressListeners@resource://gre/modules/RemoteWebProgress.jsm:78:16
[task 2020-04-17T17:18:10.990Z] 17:18:10     INFO - onStateChange@resource://gre/modules/RemoteWebProgress.jsm:88:10
[task 2020-04-17T17:18:10.990Z] 17:18:10     INFO - 
[task 2020-04-17T17:18:10.990Z] 17:18:10     INFO - Buffered messages finished
[task 2020-04-17T17:18:10.991Z] 17:18:10     INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_ElapsedTime.js | Test timed out - 
[task 2020-04-17T17:18:10.991Z] 17:18:10     INFO - GECKO(6448) | MEMORY STAT heapAllocated not supported in this build configuration.
[task 2020-04-17T17:18:10.991Z] 17:18:10     INFO - GECKO(6448) | MEMORY STAT | vsize 19406252MB | vsizeMaxContiguous 67323398MB | residentFast 1155MB
[task 2020-04-17T17:18:10.991Z] 17:18:10     INFO - TEST-OK | dom/ipc/tests/browser_ElapsedTime.js | took 90179ms
[task 2020-04-17T17:18:10.991Z] 17:18:10     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-04-17T17:18:10.991Z] 17:18:10     INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_ElapsedTime.js | Found a tab after previous test timed out: https://example.com/browser/dom/ipc/tests/elapsed_time.sjs - 
[task 2020-04-17T17:18:10.991Z] 17:18:10     INFO - checking window state
[task 2020-04-17T17:18:11.016Z] 17:18:11     INFO - TEST-START | dom/ipc/tests/browser_ProcessPriorityManager.js
Flags: needinfo?(nkochar)
Whiteboard: [stockwell needswork:owner]
Assignee: nobody → apavel
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Pushed by nbeleuzu@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/2e3a41bbd8b7 disable browser_ElapsedTime.js on linux and win to reduce failures r=egao
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla77
Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
Target Milestone: mozilla77 → ---

This is failing on win 7 platform, since the disable patch landed. There already are 12 failures in the last 10 hours, I've made another patch and updated disable condition for win platform.

Pushed by ccoroiu@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/002052b4688c update disable condition for browser_ElapsedTime.js on win platform r=egao

I was on leave when the NI was added. I just got back but I see that this is very low occurrence rate.

Flags: needinfo?(nkochar)

This test has been removed in https://phabricator.services.mozilla.com/D80127#change-elq2uZSyhDut in bug 1646582 so closing this bug as invalid.

Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Keywords: leave-open
Resolution: --- → INVALID
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: