Closed Bug 1282269 Opened 3 years ago Closed 4 months ago

Intermittent devtools/client/framework/test/browser_browser_toolbox_debugger.js | application timed out after 330/370 seconds with no output

Categories

(DevTools :: Debugger, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED FIXED

People

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

Details

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

Attachments

(1 file)

Priority: -- → P3
this seems to have started around May 4th and continues at a pretty decent rate:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1282269&startday=2017-05-01&endday=2017-05-30&tree=all

primarily on linux64 debug (although the linux64 failures stopped around May 26th and are now windows 7 mostly)

here is linux64 log:
https://treeherder.mozilla.org/logviewer.html#?repo=try&job_id=102500015&lineNumber=4944

and the related screenshot:
https://public-artifacts.taskcluster.net/T09Zz0zCQRukwkbaxe4qDw/0/public/test_info//mozilla-test-fail-screenshot_fjhx2t.png


looking on win7 opt (recent failures):
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=103121793&lineNumber=3288

I see this screenshot:
http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/321569dc3990effd53a6c5e86346c2333f2976fb14fd258c84b43221c3807d71d2cf100e6cb507f4d2310690db853921c96f827f3f3a6d46e4154538666e609a

with log messages like this:
12:29:53     INFO - Opening the browser toolbox
12:29:53     INFO - 
12:29:53     INFO - Buffered messages logged at 12:24:17
12:29:53     INFO - TEST-PASS | devtools/client/framework/test/browser_browser_toolbox_debugger.js | Browser toolbox started
12:29:53     INFO -  - 
12:29:53     INFO - Buffered messages logged at 12:24:22
12:29:53     INFO - Console message: [JavaScript Warning: "DebuggeeWouldRun: debuggee `resource://gre/modules/commonjs/toolkit/loader.js:864' would run" {file: "resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/builtin-modules.js" line: 152}]
12:29:53     INFO - Buffered messages logged at 12:24:23
12:29:53     INFO - Console message: [JavaScript Warning: "DebuggeeWouldRun: debuggee `resource://gre/modules/PromiseWorker.jsm:215' would run" {file: "resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/script.js" line: 357}]
12:29:53     INFO - Buffered messages finished
12:29:53     INFO - TEST-UNEXPECTED-TIMEOUT | devtools/client/framework/test/browser_browser_toolbox_debugger.js | application timed out after 330 seconds with no output
12:29:53    ERROR - Force-terminating active process(es).


I suspect this is the same failure for linux64 debug and win7*;

:jlast, can you take a look at this test case and help make it more robust?
Flags: needinfo?(jlaster)
Whiteboard: [stockwell needswork]
last week this has lower rates, and it seems to be on the lower end for this week so far.
Flags: needinfo?(jlaster)
Whiteboard: [stockwell needswork] → [stockwell unknown]
this has increased sharply in failures on june 13th and on june 16th, for example in 3.5 days there are 76 failures.

:jlast, as this is really frequent can you help find someone on the devtools debugger team to resolve this bug this week (fixed, reduced, disabled)?  I am fine disabling this if that is needed.
Flags: needinfo?(jlaster)
Whiteboard: [stockwell unknown] → [stockwell needswork]
with 60+ failures in the last 2 days, and no indication a fix is on the way, lets disable this to reduce the pain.
Attachment #8879900 - Flags: review?(gbrown)
Attachment #8879900 - Flags: review?(gbrown) → review+
Pushed by jmaher@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/19c219862e41
Intermittent devtools/client/framework/test/browser_browser_toolbox_debugger.js. temporarily disable on debug. r=gbrown
Keywords: leave-open
Whiteboard: [stockwell needswork] → [stockwell disabled]
still keeping an eye on this bug since opt/asan failures are pretty high.
Whiteboard: [stockwell disabled] → [stockwell needswork]
:jlast, is this going to be deprecated in when 56 goes to beta?
This bug will still be relevant. It tests the new debugger in the browser toolbox. We should look into it.
Flags: needinfo?(jlaster)
This bug has been hitting a lot on Beta since 56 was uplifted to it. Any chance we can bump the priority on it before resorting to disabling instead?
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1282269&startday=2017-08-02&tree=mozilla-beta
Flags: needinfo?(jlaster)
It looks like tests that fail have this error:

will dig more into this tomorrow

>    INFO - checking window state
>    INFO - TEST-START | devtools/client/framework/test/browser_browser_toolbox.js
>    INFO - GECKO(1700) | 1501951988610	Marionette	INFO	Enabled via MOZ_MARIONETTE
>    INFO - GECKO(1700) | JavaScript error: resource://gre/modules/XPCOMUtils.jsm, line 192: TypeError: can't redefine non-configurable property "Services"
>    INFO - GECKO(1700) | JavaScript warning: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/builtin-modules.js, line 152: DebuggeeWouldRun: debuggee `resource://gre/modules/commonjs/toolkit/loader.js:864' would run
>    INFO - GECKO(1700) | JavaScript error: resource:///modules/BrowserUsageTelemetry.jsm, line 333: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIObserverService.removeObserver]
>    INFO - GECKO(1700) | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping
>    INFO - GECKO(1700) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
>    INFO - GECKO(1700) | MEMORY STAT | vsize 4149MB | residentFast 305MB | heapAllocated 153MB
>    INFO - TEST-OK | devtools/client/framework/test/browser_browser_toolbox.js | took 5234ms
>    INFO - checking window state
>    INFO - TEST-START | devtools/client/framework/test/browser_browser_toolbox_debugger.js
>    INFO - GECKO(1700) | 1501951993842	Marionette	INFO	Enabled via MOZ_MARIONETTE
>    INFO - GECKO(1700) | JavaScript error: resource://gre/modules/XPCOMUtils.jsm, line 192: TypeError: can't redefine non-configurable property "Services"
>    INFO - GECKO(1700) | START: 958
>    INFO - GECKO(1700) | Waiting for debugger load
>    INFO - GECKO(1700) | Waiting on sources: http://mozilla.org/browser-toolbox-test.js
>    INFO - GECKO(1700) | Loaded, selecting the test script to debug
>    INFO - GECKO(1700) | Waiting for thread event 'paused' to fire.
>    INFO - GECKO(1700) | Waiting for ADD_BREAKPOINT to dispatch 1 time(s)
>    INFO - GECKO(1700) | Thread event 'paused' fired.
>    INFO - GECKO(1700) | ADD_BREAKPOINT dispatched 1 time(s)
>    INFO - GECKO(1700) | JavaScript warning: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/builtin-modules.js, line 152: DebuggeeWouldRun: debuggee `resource://gre/modules/commonjs/toolkit/loader.js:864' would run
>    INFO - GECKO(1700) | SUCCESS: '"server3.conn0.source369"' is equal to '"server3.conn0.source369"'
>    INFO - GECKO(1700) | SUCCESS: '"server3.conn0.source369"' is equal to '"server3.conn0.source369"'
>    INFO - GECKO(1700) | SUCCESS: '2' is equal to '2'
>    INFO - GECKO(1700) | JavaScript warning: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/script.js, line 356: DebuggeeWouldRun: debuggee `resource://gre/modules/subprocess/subprocess_common.jsm:101' would run
>    INFO - GECKO(1700) | JavaScript warning: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/script.js, line 356: DebuggeeWouldRun: debuggee `chrome://mochikit/content/browser-test.js:374' would run
>    INFO - Buffered messages logged at 09:53:13
>    INFO - Entering test bound runTest
>    INFO - Opening the browser toolbox
These two ones highlight a failure:
https://treeherder.mozilla.org/logviewer.html#?job_id=121751860&repo=mozilla-beta&lineNumber=2542
https://treeherder.mozilla.org/logviewer.html#?job_id=121751743&repo=mozilla-beta&lineNumber=2541

18:47:32     INFO -  GECKO(1088) | ADD_BREAKPOINT dispatched 1 time(s)
18:47:32     INFO -  GECKO(1088) | JavaScript warning: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/builtin-modules.js, line 152: DebuggeeWouldRun: debuggee `resource://gre/modules/commonjs/toolkit/loader.js:864' would run
18:47:32     INFO -  GECKO(1088) | SUCCESS: '"server3.conn0.source391"' is equal to '"server3.conn0.source391"'JavaScript warning: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/script.js, line 356: DebuggeeWouldRun: debuggee `resource://gre/modules/subprocess/subprocess_common.jsm:101' would run
18:47:32     INFO -  GECKO(1088) | JavaScript warning: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/script.js, line 356: DebuggeeWouldRun: debuggee `chrome://mochikit/content/browser-test.js:374' would run
18:47:33     INFO -  GECKO(1088) | JavaScript error: chrome://devtools/content/framework/toolbox-process-window.js, line 146: Error: FAILURE: '"server3.conn0.source366"' is equal to '"server3.conn0.source391"'
18:53:03     INFO -  Buffered messages logged at 18:47:29

It looks like this assertion sometimes fail:
  http://searchfox.org/mozilla-central/source/devtools/client/debugger/new/test/mochitest/head.js#221
I imagine we call it from here:
  http://searchfox.org/mozilla-central/source/devtools/client/framework/test/test_browser_toolbox_debugger.js#38
Any idea why it would race?
May be we don't wait correctly before asserting?

This one seems to fail on the second call to assertPausedLocation:
  https://treeherder.mozilla.org/logviewer.html#?job_id=121733836&repo=mozilla-beta&lineNumber=2915
Jason, It looks like it can still fail. May be less frequently?
It failed once on this try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=99d2a8cb3eecbdb4793d5da0f46e0e80de409639
Look at Window 7 opt runs:

19:06:29     INFO -  GECKO(3036) | Waiting for debugger load
19:06:29     INFO -  GECKO(3036) | Waiting on sources: http://mozilla.org/browser-toolbox-test.js
19:06:29     INFO -  GECKO(3036) | Loaded, selecting the test script to debug
19:06:29     INFO -  GECKO(3036) | Waiting for thread event 'paused' to fire.
19:06:29     INFO -  GECKO(3036) | Waiting for ADD_BREAKPOINT to dispatch 1 time(s)
19:06:29     INFO -  GECKO(3036) | Thread event 'paused' fired.
19:06:29     INFO -  GECKO(3036) | JavaScript warning: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/builtin-modules.js, line 157: DebuggeeWouldRun: debuggee `resource://gre/modules/commonjs/toolkit/loader.js:864' would run
19:06:30     INFO -  GECKO(3036) | ADD_BREAKPOINT dispatched 1 time(s)
19:06:30     INFO -  GECKO(3036) | SUCCESS: '"server3.conn0.source391"' is equal to '"server3.conn0.source391"'JavaScript warning: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/script.js, line 356: DebuggeeWouldRun: debuggee `resource://gre/modules/subprocess/subprocess_common.jsm:101' would run
19:06:30     INFO -  GECKO(3036) | JavaScript warning: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/script.js, line 356: DebuggeeWouldRun: debuggee `chrome://mochikit/content/browser-test.js:374' would run
19:06:31     INFO -  GECKO(3036) | JavaScript error: chrome://devtools/content/framework/toolbox-process-window.js, line 146: Error: FAILURE: '"server3.conn0.source378"' is equal to '"server3.conn0.source391"'

I launched a bunch of new runs to see how intermittent it is...
this bug has been failing very frequently on mozilla-beta, I recommend disabling it for beta given the longer history of failures.

:ryanvm, can you do that?
Flags: needinfo?(ryanvm)
Whiteboard: [stockwell needswork] → [stockwell disabled]
Bulk priority update of open intermittent test failure bugs. 

P3 => P5

https://bugzilla.mozilla.org/show_bug.cgi?id=1381960
Priority: P3 → P5
Flags: needinfo?(jlaster)
Product: Firefox → DevTools
Summary: Intermittent devtools/client/framework/test/browser_browser_toolbox_debugger.js | application timed out after 330 seconds with no output → Intermittent devtools/client/framework/test/browser_browser_toolbox_debugger.js | application timed out after 330/370 seconds with no output
Status: NEW → RESOLVED
Closed: 4 months ago
Resolution: --- → FIXED
Assignee: nobody → jmaher
You need to log in before you can comment on or make changes to this bug.