Closed Bug 1163212 Opened 9 years ago Closed 8 years ago

Intermittent test_Debugger.Source.prototype.element.html | SVGLoad event handler belongs to albrecht

Categories

(DevTools :: Debugger, defect)

Product:
DevTools
Component:
Debugger
Platform:
Unspecified
Windows 8
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox49 fixed, firefox-esr45 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 49
Tracking Flags:
Tracking Status
firefox49 --- fixed
firefox-esr45 --- fixed

People

(Reporter: KWierso, Assigned: mattwoodrow)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

resize-not-cancelable
1.05 KB, patch
smaug
: review+
Details | Diff | Splinter Review
resize-not-cancelable_esr45
601 bytes, patch
masayuki
: review+
Details | Diff | Splinter Review 
15:12:41 INFO - 2927 INFO TEST-START | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html
15:12:41 INFO - MEMORY STAT vsize after test: 1171513344
15:12:41 INFO - MEMORY STAT vsizeMaxContiguous after test: 7943869530112
15:12:41 INFO - MEMORY STAT residentFast after test: 398487552
15:12:41 INFO - MEMORY STAT heapAllocated after test: 184517110
15:12:41 INFO - 2928 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | top frame is franz
15:12:41 INFO - 2929 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | top frame source belongs to element franz
15:12:41 INFO - 2930 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | top frame source doesn't belong to an attribute
15:12:41 INFO - 2931 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | second frame source belongs to element heinrich
15:12:41 INFO - 2932 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | second frame source doesn't belong to an attribute
15:12:41 INFO - 2933 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | third frame source belongs to element heidi
15:12:41 INFO - 2934 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | third frame source belongs to 'onclick' attribute
15:12:41 INFO - 2935 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | top frame belongs to ulrich
15:12:41 INFO - 2936 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | top frame is not on an attribute of ulrich
15:12:41 INFO - 2937 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | top frame belongs to isolde
15:12:41 INFO - 2938 INFO frame.script.source.element is: ({})
15:12:41 INFO - 2939 INFO toString: [object HTMLScriptElement]
15:12:41 INFO - 2940 INFO id: idolde, my dear
15:12:41 INFO - 2941 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | top frame source is not an attribute of isolde
15:12:41 INFO - 2942 INFO frame.script.source.elementAttributeName is: (void 0)
15:12:41 INFO - 2943 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | second event's handler belongs to dieter
15:12:41 INFO - 2944 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | second event's handler is on dieter's 'ondrag' element
15:12:41 INFO - 2945 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | onresize event handler belongs to body element
15:12:41 INFO - 2946 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | onresize event handler is on body element's 'onresize' attribute
15:12:41 INFO - 2947 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | SVGLoad event handler belongs to albrecht
15:12:41 INFO - 2948 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | SVGLoad event handler is on albrecht's 'onload' attribute
15:12:41 INFO - 2949 INFO TEST-PASS | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | all tests actually ran
15:12:41 INFO - 2950 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | SVGLoad event handler belongs to albrecht - expected PASS
15:12:41 INFO - 2951 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | SVGLoad event handler is on albrecht's 'onload' attribute - expected PASS
15:12:41 INFO - 2952 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | all tests actually ran - expected PASS
15:12:41 INFO - 2953 ERROR [SimpleTest.finish()] this test already called finish!
15:12:41 INFO - 2954 INFO TEST-UNEXPECTED-ERROR | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | called finish() multiple times
15:12:41 INFO - TEST-INFO took 75ms
15:12:41 INFO - 2955 INFO TEST-OK | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html |
15:12:41 INFO - 2956 INFO TEST-START | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.introductionScript.html
[Mass Closure] Closing Intermittent as a one off
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → WORKSFORME
This seems to have spiked lately, reopening.

As far as I can tell, it started somewhere in this range: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&fromchange=4ac6078ac2b44ad603a02fca4d0d3375f9f4e71c&group_state=expanded&filter-searchStr=(oth windows&tochange=daec005079bf4bb03c8d973986e11ba8a5d8345f&selectedJob=28476942 with the earliest instances being on the push for Bug 881832.
Status: RESOLVED → REOPENED
Flags: needinfo?(matt.woodrow)
Resolution: WORKSFORME → ---
That bug changed timings in layout, so it's believable that it made an existing intermittent more frequent.

Probably still easiest for the owner of the test to look into this.
Flags: needinfo?(matt.woodrow)
Yes, it definitely makes sense for me to take care of this. I just need to be able to reproduce.
Assignee: nobody → jimb
You'll want to pull from inbound to reproduce since I got backed out.
Having an initial look at this myself since getting my code re-landed is a priority for me.

The first failure is 'top frame belongs to isolde', which is the same as we had with bug 1162067.

The debug info printed is:

INFO frame.script.source.element is: ({})
INFO    toString: [object HTMLBodyElement]
INFO id: 
INFO frame.script.source.elementAttributeName is: "onresize" 

This looks what I think we'd expect if a resize event was being incorrectly caught, and we're hitting the 'debugger;' call attached to the body's onresize handler.

The rest of the failures happen because 'SVGLoadHandler' gets called a second time, which sort of makes sense if we have extra events coming in that we didn't expect.

I'm not really sure how we passed 'dieter' though, since it seems like the 'isolde' event should happen before it.

Anyway, having a look at the event code, it looks like eResize has mCancelable=true by default [1], so it seems like bug 1162067's attempt to prevent this won't work.

My patches make resizing deferred, so it almost certainly changed the timing of when the resize event gets fired.

[1] http://mxr.mozilla.org/mozilla-central/source/widget/BasicEvents.h#271
Well, the spec says that resize events aren't cancelable.

We're definitely getting one though, and the test hasn't issued a manual resize event at this point.

I'm quite confused, is gecko doing the wrong thing here? 

I had a look at when the original fix landed and it looks like we always had cancelable=true, so how did the original fix work?

I don't know what bug smaug was referring to (in bug 1162067), so it's possible he backed out and the problem went away because of that, possibly to come back later as this bug (but at a much lower frequency?).
Thanks very much for looking into this. I understood only enough about what's going on to write the test, nothing more. Let me re-state what I think you're saying:

Given the debug info printed that you mention in comment 11, it seems pretty clear that we're running the handler in Debugger.Source.prototype.element.html:

<body onresize='if (event.cancelable) debugger;'>

But somehow we're hitting that debugger statement while dbg.onDebuggerStatement is still set to isoldeDebuggerHandler, given the failure message. This is before the code here, that synthesizes a cancelable resize event:

https://hg.mozilla.org/mozilla-central/file/3b45aeb5288a/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html#l133

The failure shown in comment 0 includes the messages "SVGLoad event handler belongs to albrecht", "SVGLoad event handler is on albrecht's 'onload' attribute", and "all tests actually ran" twice, passing the first time, and failing the second time. This also points to an unexpected execution of a `debugger` statement. It might be helpful to put a copy of the code from isoldeDebuggerHandler in SVGLoadHandler as well, to see which debugger statement it is:

    info("frame.script.source.element is: " + uneval(frame.script.source.element));
    if (typeof frame.script.source.element.unsafeDereference() == 'object') {
       info("   toString: " + frame.script.source.element.unsafeDereference());
       info("   id: " + frame.script.source.element.unsafeDereference().id);
    }

If it's the cancelable resize again, then we know we're getting too many of those.

Would event propagation cause the handler to run multiple times?
Yeah, that all sounds correct.

The important part is that it appears that normal resize events from gecko have event.cancelable=true, so the check in the handler isn't doing anything useful.

Changing it to 'if (!event.cancelable) debugger;' would fix this I think, but maybe we should look into why gecko isn't following the spec.

Smaug, any idea why we have cancelable=true for resize events?
Flags: needinfo?(bugs)
Because they have been cancelable in Gecko since the beginning of the time (my guess)?
If the spec says they should not be cancelable and they aren't in other browsers, we should definitely fix them.
Flags: needinfo?(bugs)
And the resize event handling bug I was referring in the other bug is
https://bugzilla.mozilla.org/show_bug.cgi?id=1149555
which is about the time when resize is supposed to fire.
Safari and Chrome both have the resize event as not cancelable.

Let's see if we have any tests that depend on the current behaviour:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0b6fc0333e71
Seems ok, except that Win7 clipboard tests are all broken on automation (not related to this patch).
Assignee: jimb → matt.woodrow
Attachment #8756640 - Flags: review?(bugs)
Comment on attachment 8756640 [details] [diff] [review]
resize-not-cancelable

Hmm, per spec resize does not bubble. But that is riskier change, since it might break addons and even our chrome.
So better to do that separately. 
Want to file a new bug for that. Core: Layout I guess, given that resize is a layout feature.
Attachment #8756640 - Flags: review?(bugs) → review+
The test is trying to exercise a corner case:

<!-- HTML requires some body element onfoo attributes to add handlers to the
     *window*, not the element --- but Debugger.Source.prototype.element should
     return the element. Here, that rule should apply to the body's 'onresize'
     handler. (For the reason for the 'cancelable' check, see the code that
     sends the event.) -->

So I don't think other kinds of events would necessarily work. But the only role the cancelable flag plays is to help us distinguish the synthetic event we send from genuine events generated by Firefox while the test runs. If there is any other characteristic of the event that chrome can set and that content can see, that would do just as well as the cancelable property:

    // Try sending an 'onresize' event to the window.
    //
    // Note that we only want Debugger to see the events we send, not any
    // genuine resize events accidentally generated by the test harness (see bug
    // 1162067). So we mark our events as cancelable; that seems to be the only
    // bit chrome can fiddle on an Event that content code will see and that
    // won't affect propagation. Then, the content event only runs its
    // 'debugger' statement when the event is cancelable. It's a kludge.
That said, if fixing the cancelable flag is easy, then that should be fine.
https://hg.mozilla.org/mozilla-central/rev/a0365d37a510
Status: REOPENED → RESOLVED
Closed: 9 years ago → 8 years ago
status-firefox49: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 49
What the robot is trying to say, despite its alarming language, is that there have been no occurrences of this orange since Tuesday. Which would be great, except for the fact that the patch didn't land until Friday.

Let's leave this closed and see what the coming weeks bring.
Since bug 881832 was uplifted to ESR45, we're hitting these failures there now as well. Since Matt's away until next week, can you please provide a rebased patch for this bug, Olli?
Flags: needinfo?(bugs)
This is different enough from m-c patch that this needs a quick review
Flags: needinfo?(bugs)
Attachment #8816441 - Flags: review?(masayuki)
Comment on attachment 8816441 [details] [diff] [review]
resize-not-cancelable_esr45

Hmm, we could have a method which returns cancelable value of standardized spec, though.
Attachment #8816441 - Flags: review?(masayuki) → review+
We have better setup in m-c. The patch is for esr45 only.
Blocks: 881832
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: