Closed Bug 1113935 Opened 10 years ago Closed 6 years ago

Intermittent browser_dbg_bfcache.js | Found the expected number of sources. - Got 0, expected 1 | Found the single source label.

Categories

(DevTools :: Debugger, defect, P3)

Product:
DevTools
Component:
Debugger
Platform:
x86_64
Linux
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: RyanVM, Assigned: fitzgen)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

intermittent-bf-cache.patch
3.45 KB, patch
vporof
: review+
fitzgen
: checkin+
Details | Diff | Splinter Review
15:33:19 INFO - 180 INFO TEST-START | browser/devtools/debugger/test/browser_dbg_bfcache.js 15:33:20 INFO - Frame script loaded. 15:33:20 INFO - -*-*- UserCustomizations (parent): document created: http://example.com/browser/browser/devtools/debugger/test/doc_script-switching-01.html 15:33:20 INFO - -*-*- UserCustomizations (parent): _injectInWindow 15:33:20 INFO - -*-*- UserCustomizations (parent): principal status: 0 15:33:22 INFO - -*-*- UserCustomizations (parent): document created: http://example.com/browser/browser/devtools/debugger/test/doc_recursion-stack.html 15:33:22 INFO - -*-*- UserCustomizations (parent): _injectInWindow 15:33:22 INFO - -*-*- UserCustomizations (parent): principal status: 0 15:33:23 INFO - -*-*- UserCustomizations (parent): document created: http://example.com/browser/browser/devtools/debugger/test/doc_script-switching-01.html 15:33:23 INFO - -*-*- UserCustomizations (parent): _injectInWindow 15:33:23 INFO - -*-*- UserCustomizations (parent): principal status: 0 15:33:24 INFO - 181 INFO checking window state 15:33:24 INFO - 182 INFO Initializing a debugger panel. 15:33:24 INFO - 183 INFO Adding tab: http://example.com/browser/browser/devtools/debugger/test/doc_script-switching-01.html 15:33:24 INFO - 184 INFO Loading frame script with url chrome://mochitests/content/browser/browser/devtools/debugger/test/code_frame-script.js. 15:33:24 INFO - 185 INFO Tab added and finished loading: http://example.com/browser/browser/devtools/debugger/test/doc_script-switching-01.html 15:33:24 INFO - 186 INFO Debugee tab added successfully: http://example.com/browser/browser/devtools/debugger/test/doc_script-switching-01.html 15:33:24 INFO - 187 INFO Debugger panel shown successfully. 15:33:24 INFO - 188 INFO Debugger client resumed successfully. 15:33:24 INFO - 189 INFO Testing first page. 15:33:24 INFO - 190 INFO Waiting for debugger event: 'Debugger:EditorSourceShown' to fire: 1 time(s). 15:33:24 INFO - 191 INFO Waiting for editor event: 'cursorActivity' to fire: 1 time(s). 15:33:24 INFO - 192 INFO Waiting for debugger event: 'Debugger:FetchedScopes' to fire: 1 time(s). 15:33:24 INFO - 193 INFO Editor event 'cursorActivity' fired: 1 time(s). 15:33:24 INFO - 194 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Enough 'cursorActivity' editor events have been fired. 15:33:24 INFO - 195 INFO Caret updated: 1, 1 15:33:24 INFO - 196 INFO Current editor caret position: 1, 1 15:33:24 INFO - 197 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | The correct caret position has been set. 15:33:24 INFO - 198 INFO Debugger event 'Debugger:EditorSourceShown' fired: 1 time(s). 15:33:24 INFO - 199 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Enough 'Debugger:EditorSourceShown' panel events have been fired. 15:33:24 INFO - 200 INFO Source shown: http://example.com/browser/browser/devtools/debugger/test/code_script-switching-01.js 15:33:24 INFO - 201 INFO Waiting for debugger event: 'Debugger:EditorSourceShown' to fire: 1 time(s). 15:33:24 INFO - 202 INFO Debugger event 'Debugger:FetchedScopes' fired: 1 time(s). 15:33:24 INFO - 203 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Enough 'Debugger:FetchedScopes' panel events have been fired. 15:33:24 INFO - 204 INFO Debugger event 'Debugger:EditorSourceShown' fired: 1 time(s). 15:33:24 INFO - 205 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Enough 'Debugger:EditorSourceShown' panel events have been fired. 15:33:24 INFO - 206 INFO Source shown: http://example.com/browser/browser/devtools/debugger/test/code_script-switching-02.js 15:33:24 INFO - 207 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | The correct source has been shown. 15:33:24 INFO - 208 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the expected number of sources. 15:33:24 INFO - 209 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the first source label. 15:33:24 INFO - 210 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the second source label. 15:33:24 INFO - 211 INFO Navigating to a different page. 15:33:24 INFO - 212 INFO Waiting for debugger event: 'Debugger:SourcesAdded' to fire: 1 time(s). 15:33:24 INFO - 213 INFO Debugger event 'Debugger:SourcesAdded' fired: 1 time(s). 15:33:24 INFO - 214 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Enough 'Debugger:SourcesAdded' panel events have been fired. 15:33:24 INFO - 215 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the expected number of sources. 15:33:24 INFO - 216 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the single source label. 15:33:24 INFO - 217 INFO Going back. 15:33:24 INFO - 218 INFO Waiting for debugger event: 'Debugger:SourcesAdded' to fire: 1 time(s). 15:33:24 INFO - 219 INFO Debugger event 'Debugger:SourcesAdded' fired: 1 time(s). 15:33:24 INFO - 220 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Enough 'Debugger:SourcesAdded' panel events have been fired. 15:33:24 INFO - 221 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the expected number of sources. 15:33:24 INFO - 222 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the first source label. 15:33:24 INFO - 223 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the second source label. 15:33:24 INFO - 224 INFO Going forward. 15:33:24 INFO - 225 INFO Waiting for debugger event: 'Debugger:SourcesAdded' to fire: 1 time(s). 15:33:24 INFO - 226 INFO Debugger event 'Debugger:SourcesAdded' fired: 1 time(s). 15:33:24 INFO - 227 INFO TEST-PASS | browser/devtools/debugger/test/browser_dbg_bfcache.js | Enough 'Debugger:SourcesAdded' panel events have been fired. 15:33:24 INFO - 228 INFO TEST-UNEXPECTED-FAIL | browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the expected number of sources. - Got 0, expected 1 15:33:24 INFO - Stack trace: 15:33:24 INFO - chrome://mochikit/content/browser-test.js:test_is:837 15:33:24 INFO - chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js:validateSecondPage:80 15:33:24 INFO - chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js:testForward/<:66 15:33:24 INFO - resource://gre/modules/devtools/deprecated-sync-thenables.js:resolve:40 15:33:24 INFO - resource://gre/modules/devtools/deprecated-sync-thenables.js:then:20 15:33:24 INFO - resource://gre/modules/devtools/deprecated-sync-thenables.js:resolve:72 15:33:24 INFO - chrome://mochitests/content/browser/browser/devtools/debugger/test/head.js:onEvent:368 15:33:24 INFO - resource://gre/modules/devtools/event-emitter.js:EventEmitter_emit:137 15:33:24 INFO - chrome://browser/content/devtools/debugger-controller.js:SourceScripts.prototype._onSourcesAdded:1213 15:33:24 INFO - resource://gre/modules/devtools/dbg-client.jsm:DebuggerClient.requester/</<:349 15:33:24 INFO - resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:makeInfallible/<:83 15:33:24 INFO - resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/event/core.js:emit:97 15:33:24 INFO - resource://gre/modules/devtools/dbg-client.jsm:Request.prototype.emit:1106 15:33:24 INFO - resource://gre/modules/devtools/dbg-client.jsm:DebuggerClient.prototype.onPacket:946 15:33:24 INFO - resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:LocalDebuggerTransport.prototype.send/<:545 15:33:24 INFO - resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:makeInfallible/<:83 15:33:24 INFO - resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:makeInfallible/<:83 15:33:24 INFO - null:null:0 15:33:24 INFO - 229 INFO TEST-UNEXPECTED-FAIL | browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the single source label. - 15:33:24 INFO - Stack trace: 15:33:24 INFO - chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js:validateSecondPage:82 15:33:24 INFO - chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js:testForward/<:66 15:33:24 INFO - resource://gre/modules/devtools/deprecated-sync-thenables.js:resolve:40 15:33:24 INFO - resource://gre/modules/devtools/deprecated-sync-thenables.js:then:20 15:33:24 INFO - resource://gre/modules/devtools/deprecated-sync-thenables.js:resolve:72 15:33:24 INFO - chrome://mochitests/content/browser/browser/devtools/debugger/test/head.js:onEvent:368 15:33:24 INFO - resource://gre/modules/devtools/event-emitter.js:EventEmitter_emit:137 15:33:24 INFO - chrome://browser/content/devtools/debugger-controller.js:SourceScripts.prototype._onSourcesAdded:1213 15:33:24 INFO - resource://gre/modules/devtools/dbg-client.jsm:DebuggerClient.requester/</<:349 15:33:24 INFO - resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:makeInfallible/<:83 15:33:24 INFO - resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/event/core.js:emit:97 15:33:24 INFO - resource://gre/modules/devtools/dbg-client.jsm:Request.prototype.emit:1106 15:33:24 INFO - resource://gre/modules/devtools/dbg-client.jsm:DebuggerClient.prototype.onPacket:946 15:33:24 INFO - resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:LocalDebuggerTransport.prototype.send/<:545 15:33:24 INFO - resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:makeInfallible/<:83 15:33:24 INFO - resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:makeInfallible/<:83 15:33:24 INFO - null:null:0 15:33:25 INFO - 230 INFO TEST-OK | browser/devtools/debugger/test/browser_dbg_bfcache.js | took 5611ms
Blocks: dbg-test
This specific bug (test + failure + asan linux64) is showing up 80% of the time on --run-by-dir for the 'dt' job. As this started recently, currently I have done a lot of dt retriggers on treeherder: https://treeherder.mozilla.org/#/jobs?repo=fx-team&searchQuery=devtools&filter-searchStr=asan%20devtools&fromchange=eef487a50fb0&tochange=8d1c3083f7e6 Quite possibly we will find the root cause of the changeset which caused this. This is much more frequent in --run-by-dir, so either this failure is related to something in a previous test or the fact that we are starting up and terminating the browser much quicker. Victor, you were one of the last people to change this test case, do you have any thoughts on why it might be occurring?
ok, maybe retriggers later and bug 1106695 is the root cause of this intermittent: https://hg.mozilla.org/integration/fx-team/pushloghtml?changeset=30226ebe3c5e Nick, you are the original author of the patches in bug 1106695, do you have any ideas of why we are seeing browser_dbg_bfcache.js acting up as a side effect of your patch?
Depends on: 1106695
Flags: needinfo?(nfitzgerald)
A couple of observations: * Looks like when it fails it is always in `testForward`, not any other direction. * It doesn't seem like one of our classic GC-sensitivity bugs because the test files all define functions, so the sources shouldn't be getting GC'd. I don't see how my patch could have made this trigger more often -- if anything I would have expected *less*. Perhaps when moving forward through history the page isn't in the cache like we expect and we are fetching sources before the page's "load" event has fired and the source hasn't been evaluated yet? Here is a try push with more logging enabled: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=4444c1de2edb Hopefully that will give us more to work with.
Flags: needinfo?(nfitzgerald)
thanks Nick! Do feel free to ping me if you have ideas to try out and need a few spare cycles.
I looked at the try push (https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=4444c1de2edb), and tried to extract some useful information: passed: http://pastebin.mozilla.org/8165593 failed: http://pastebin.mozilla.org/8165592 Really the difference is on line 161. What is even more strange is that in the passing case there is no calls to test-pass or any type of status from the test itself, but the failure one has a lot of passes and one failure. The failing one also cleans up after the test: INFO - 233 INFO Removing tab. INFO - 234 INFO Tab removed and finished closing. INFO - 235 INFO finish() was called, cleaning up... INFO - 236 INFO Forcing GC after debugger test. My general interpretation is that this test is not running at all, and when it does we fail. Nick, can you comment on this? Are you interpretting this the same as I am?
Flags: needinfo?(nfitzgerald)
Yeah, good catch! It seems like just opening the debugger panel is failing in the "passing" test case. There is no message about "Debugger panel shown" when the test does not fail.
Flags: needinfo?(nfitzgerald)
is this something you can fix or give some instruction on so someone else could take a stab at fixing it?
Attached patch intermittent-bf-cache.patch (obsolete) — — Splinter Review
I modified the test so that it runs in Task.jsm which has better error reporting. So I would expect this to cause the test to fail every time now, I guess? Note that it is still passing locally for me. https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=55d19400daba
Assignee: nobody → nfitzgerald
Status: NEW → ASSIGNED
(In reply to Joel Maher (:jmaher) from comment #46) > is this something you can fix or give some instruction on so someone else > could take a stab at fixing it? I don't understand why opening the debugger panel could fail under these conditions. So "hopefully", and "probably not", respectively :-/
I think that try push has a lot of failures, quite possibly it is some small thing as it looks to affect a lot of tests (maybe a bad base?)
just a friendly ping to see if this can move forward a little bit. I am open to any tasks.
Nick, can you help move this along? I am waiting on this fix to get --run-by-dir going for the devtools.
Flags: needinfo?(nfitzgerald)
I don't think this is bug 1080025, since all the sources used by this test define global functions, and so they can't be GC'd before we open the panel. I don't know why `initDebugger` isn't called (there would be a "Initializing a debugger panel" in the logs), since the very first thing that the `test` function does is call that. This leads me to believe that the `test` function isn't ever getting called either. If that is indeed what is happening, then this is a test infrastructure/framework bug. As for the test failing when `initDebugger` _is_ called: it seems like this is an existing failing test that was hidden by the other bug. I'm not sure what is going on here. Here is a new try push, hopefully on a good base this time: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=9db8266f77b4
Flags: needinfo?(nfitzgerald)
Nick, this try run you did looks pretty green. Are you ready for review?
Flags: needinfo?(nfitzgerald)
(In reply to Joel Maher (:jmaher) from comment #73) > Nick, this try run you did looks pretty green. Are you ready for review? That's really scary, because all the patch really did was add better logging :/ I guess I can remove the logging and see if the green-ness persists with the swap to Task.jsm for better error reporting...
Flags: needinfo?(nfitzgerald)
I pushed to try with the patch (removing the logging) and tested on my run-by-dir scenario: https://treeherder.mozilla.org/#/jobs?repo=try&revision=57921e830fba (linux64 asan - 2 instances) https://treeherder.mozilla.org/#/jobs?repo=try&revision=5a3c9eee8fb3 (osx 10.8 - all good) https://treeherder.mozilla.org/#/jobs?repo=try&revision=813981b385c3 (everything else - 3 instances) all in all we see this on: win7 debug x2 osx10.6 debug linux64 asan x2 :fitzgen, do let me know what is needed to get this initial patch reviewed. I know it doesn't solve this bug, but I think it helps reduce it. I would be happy to land it with my runbydir fix as well.
Flags: needinfo?(nfitzgerald)
Ok, here is that patch without logging + commit message fixed up. Victor, this changes the test entry function to be Task.jsm and removes `() => func()` for just `func`. Together, this seems to cut down on the frequency of intermittent failures of browser_dbg_bfcache.js
Flags: needinfo?(nfitzgerald)
Attachment #8549004 - Flags: review?(vporof)
Attachment #8544662 - Attachment is obsolete: true
Comment on attachment 8549004 [details] [diff] [review] intermittent-bf-cache.patch Review of attachment 8549004 [details] [diff] [review]: ----------------------------------------------------------------- Nice refactor, although I don't understand how it reduces the frequency of oranges.
Attachment #8549004 - Flags: review?(vporof) → review+
(In reply to Victor Porof [:vporof][:vp] from comment #96) > Comment on attachment 8549004 [details] [diff] [review] > intermittent-bf-cache.patch > > Review of attachment 8549004 [details] [diff] [review]: > ----------------------------------------------------------------- > > Nice refactor, although I don't understand how it reduces the frequency of > oranges. Me neither! Thanks for the review.
https://hg.mozilla.org/integration/fx-team/rev/87b85873dd84
Flags: in-testsuite+
Keywords: checkin-needed
Whiteboard: [fixed-in-fx-team]
Should I be worried that comment 101 was after run-by-dir landed on fx-team (which was itself after the push in comment 100)?
Flags: needinfo?(nfitzgerald)
(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #102) > Should I be worried that comment 101 was after run-by-dir landed on fx-team > (which was itself after the push in comment 100)? I don't _think_ so. The patch didn't end the intermittent, but seemed to make it much less frequent.
Flags: needinfo?(nfitzgerald)
Keywords: leave-open
FWIW, I discussed this with KWierso and we're both of the mind that we'd prefer to disable this test in favor of keeping run-by-dir landed if it turns out to be permafailing.
That sounds fine by me.
Is there a way to disable on TBPL, but not locally? FWIW, I've never had this test fail locally, and AFAIK no one else has either.
Attachment #8549004 - Flags: checkin+
Assignee: nfitzgerald → nobody
Status: ASSIGNED → NEW
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Product: Firefox → DevTools
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Assignee: nobody → nfitzgerald
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: