Intermittent dom/ipc/tests/browser_ElapsedTime.js | Test timed out -
Categories
(Core :: DOM: Content Processes, defect, P5)
Tracking
()
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
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 16•5 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 17•5 years ago
|
||
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=293246455&repo=mozilla-central&lineNumber=7678
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 22•5 years ago
|
||
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
Updated•5 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 25•5 years ago
|
||
Started retriggers on this range:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=Windows%2C10%2Cx64%2Casan%2CMochitests%2Ctest-windows10-64-asan%2Fopt-mochitest-browser-chrome-e10s-7%2CM%28bc7%29&tochange=bef6ce79d8f66eaf9004e2e83d9d52deb3109f05&fromchange=def5136392242e98b4b58b42d6b444d78a04bffc
Assignee | ||
Comment 26•5 years ago
|
||
Updated•5 years ago
|
Comment hidden (Intermittent Failures Robot) |
Updated•5 years ago
|
Comment 28•5 years ago
|
||
Comment 29•5 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment 31•5 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/2e3a41bbd8b7
https://hg.mozilla.org/mozilla-central/rev/09e357a32d22
Updated•5 years ago
|
Comment 32•5 years ago
|
||
Comment 33•5 years ago
|
||
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.
Comment 34•5 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment 36•5 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 45•5 years ago
|
||
I was on leave when the NI was added. I just got back but I see that this is very low occurrence rate.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 51•5 years ago
|
||
This test has been removed in https://phabricator.services.mozilla.com/D80127#change-elq2uZSyhDut in bug 1646582 so closing this bug as invalid.
Description
•