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

Status: RESOLVED FIXED

(DevTools :: Debugger, defect)

Description

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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

Comment 1

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=b2g-inbound&job_id=1880778
repository: b2g-inbound
start_time: 2015-05-08T14:58:24
who: wkocher[at]mozilla[dot]com
machine: t-w864-ix-168
buildname: Windows 8 64-bit b2g-inbound opt test mochitest-other
revision: 2f8b7d236713

2950 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | SVGLoad event handler belongs to albrecht - expected PASS
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
2952 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | all tests actually ran - expected PASS
2954 INFO TEST-UNEXPECTED-ERROR | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | called finish() multiple times
Return code: 1
Return code: 1
Return code: 1

Comment 2

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=fx-team&job_id=3010861
repository: fx-team
start_time: 2015-05-08T18:03:05
who: edilee[at]mozilla[dot]com
machine: t-snow-r4-0037
buildname: Rev4 MacOSX Snow Leopard 10.6 fx-team opt test mochitest-other
revision: 9c709ae78ec4

2863 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | SVGLoad event handler belongs to albrecht - expected PASS
2864 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
2865 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | all tests actually ran - expected PASS
2867 INFO TEST-UNEXPECTED-ERROR | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | called finish() multiple times

Comment 3

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=fx-team&job_id=3012856
repository: fx-team
start_time: 2015-05-08T21:38:25
who: philringnalda[at]gmail[dot]com
machine: t-w732-ix-033
buildname: Windows 7 32-bit fx-team pgo test mochitest-other
revision: 5751177e9259

2965 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | SVGLoad event handler belongs to albrecht - expected PASS
2966 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
2967 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | all tests actually ran - expected PASS
2969 INFO TEST-UNEXPECTED-ERROR | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | called finish() multiple times
Return code: 1
Return code: 1
Return code: 1

Comment 4

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=fx-team&job_id=3019541
repository: fx-team
start_time: 2015-05-09T16:11:45
who: philringnalda[at]gmail[dot]com
machine: t-xp32-ix-020
buildname: Windows XP 32-bit fx-team opt test mochitest-other
revision: f5a38e9aaf68

2965 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | SVGLoad event handler belongs to albrecht - expected PASS
2966 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
2967 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | all tests actually ran - expected PASS
2969 INFO TEST-UNEXPECTED-ERROR | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | called finish() multiple times
Return code: 1
Return code: 1
Return code: 1

Comment 5

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=fx-team&job_id=3018658
repository: fx-team
start_time: 2015-05-09T15:29:17
who: philringnalda[at]gmail[dot]com
machine: t-xp32-ix-040
buildname: Windows XP 32-bit fx-team pgo test mochitest-other
revision: f5a38e9aaf68

2965 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | SVGLoad event handler belongs to albrecht - expected PASS
2966 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
2967 INFO TEST-UNEXPECTED-FAIL | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | all tests actually ran - expected PASS
2969 INFO TEST-UNEXPECTED-ERROR | toolkit/devtools/server/tests/mochitest/test_Debugger.Source.prototype.element.html | called finish() multiple times
Return code: 1
Return code: 1
Return code: 1

Comment 6

[David Burns :automatedtester]

[Mass Closure] Closing Intermittent as a one off

Comment 7

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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.

Comment 8

[Matt Woodrow (:mattwoodrow)]

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.

Comment 9

[Jim Blandy :jimb]

Yes, it definitely makes sense for me to take care of this. I just need to be able to reproduce.

Comment 10

[Matt Woodrow (:mattwoodrow)]

You'll want to pull from inbound to reproduce since I got backed out.

Comment 11

[Matt Woodrow (:mattwoodrow)]

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

Comment 12

[Matt Woodrow (:mattwoodrow)]

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?).

Comment 13

[Jim Blandy :jimb]

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?

Comment 14

[Matt Woodrow (:mattwoodrow)]

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?

Comment 15

[Olli Pettay [:smaug][[e-mail]]]

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.

Comment 16

[Olli Pettay [:smaug][[e-mail]]]

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.

Comment 17

[Matt Woodrow (:mattwoodrow)]

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

Comment 18

[Matt Woodrow (:mattwoodrow)]

Attachment: resize-not-cancelable

Seems ok, except that Win7 clipboard tests are all broken on automation (not related to this patch).

Comment 19

[Olli Pettay [:smaug][[e-mail]]]

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.

Comment 20

[Jim Blandy :jimb]

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.

Comment 21

[Jim Blandy :jimb]

That said, if fixing the cancelable flag is easy, then that should be fine.

Comment 22

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/a0365d37a510

Comment 23

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/a0365d37a510

Comment 24

[Intermittent Failures Robot]

12 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 11
* try: 1

Platform breakdown:
* windows8-64: 7
* windowsxp: 3
* windows7-32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1163212&startday=2016-05-23&endday=2016-05-29&tree=all

Comment 25

[Jim Blandy :jimb]

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.

Comment 26

[Ryan VanderMeulen [:RyanVM]]

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?

Comment 27

[Olli Pettay [:smaug][[e-mail]]]

Attachment: resize-not-cancelable_esr45

This is different enough from m-c patch that this needs a quick review

Comment 28

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)]

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.

Comment 29

[Olli Pettay [:smaug][[e-mail]]]

We have better setup in m-c. The patch is for esr45 only.

Comment 30

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-esr45/rev/46163fb1cb34

Comment 31

[Intermittent Failures Robot]

9 failures in 694 pushes (0.013 failures/push) were associated with this bug in the last 7 days.  

Repository breakdown:
* mozilla-esr45: 9

Platform breakdown:
* windowsxp: 3
* osx-10-10: 3
* windows8-64: 2
* windows7-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1163212&startday=2016-11-28&endday=2016-12-04&tree=all