1451966 - Intermittent [u'svg/foreignObject-img-form-theme.html', u'==', u'svg/foreignObject-img-form-theme-ref.html'] | assertion count 1 is more than expected 0 assertions

Status: RESOLVED FIXED

(Core :: SVG, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: dluca [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=172210199&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/fk4510GDRPOJP8lFLqhBRA/runs/0/artifacts/public/logs/live_backing.log

https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/fk4510GDRPOJP8lFLqhBRA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

Comment 2

[Intermittent Failures Robot]

15 failures in 133 pushes (0.113 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-central: 7
* mozilla-inbound: 6
* autoland: 2

Platform breakdown:
* linux64-ccov: 4
* linux64: 4
* linux32: 4
* windows7-32: 2
* windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1451966&startday=2018-04-06&endday=2018-04-06&tree=trunk

Comment 3

[Cosmin Sabou [:CosminS]]

Hi! I did some retriggers to find out where this fail originated and found to be the following push: https://tinyurl.com/yceyas6s

Bas, I noticed you worked on the same folder path as the file it's failing on, https://hg.mozilla.org/integration/mozilla-inbound/rev/2926745a0fee53547f6e464321cbe4915c2fff7f, could this have something to do with bug 1440753? Please take a look at this. 
From 20 jobs this has failed 2 times on the retriggers. Thanks!

This is a part of the failure log: 
[task 2018-04-07T09:00:57.225Z] 09:00:57     INFO - REFTEST TEST-START | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/foreignObject-img-form-theme.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/foreignObject-img-form-theme-ref.html
[task 2018-04-07T09:00:57.225Z] 09:00:57     INFO - REFTEST TEST-LOAD | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/foreignObject-img-form-theme.html | 1611 / 1944 (82%)
[task 2018-04-07T09:00:57.234Z] 09:00:57     INFO - ++DOMWINDOW == 148 (0xc1da8000) [pid = 948] [serial = 5728] [outer = 0xcbe90840]
[task 2018-04-07T09:00:57.341Z] 09:00:57     INFO - REFTEST TEST-LOAD | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/foreignObject-img-form-theme-ref.html | 1611 / 1944 (82%)
[task 2018-04-07T09:00:57.349Z] 09:00:57     INFO - ++DOMWINDOW == 149 (0xc3494400) [pid = 948] [serial = 5729] [outer = 0xcbe90840]
[task 2018-04-07T09:00:57.411Z] 09:00:57     INFO - [948, Main Thread] ###!!! ASSERTION: This is unsafe! Fix the caller!: 'Error', file /builds/worker/workspace/build/src/dom/events/EventDispatcher.cpp, line 755
[task 2018-04-07T09:01:29.356Z] 09:01:29     INFO - #01: mozilla::EventDispatcher::Dispatch [dom/events/EventDispatcher.cpp:755]
[task 2018-04-07T09:01:29.356Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.357Z] 09:01:29     INFO - #02: mozilla::ScrollFrameHelper::FireScrollPortEvent [layout/generic/nsGfxScrollFrame.cpp:4493]
[task 2018-04-07T09:01:29.358Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.361Z] 09:01:29     INFO - #03: nsRootPresContext::FlushWillPaintObservers [layout/base/nsPresContext.cpp:3360]
[task 2018-04-07T09:01:29.361Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.366Z] 09:01:29     INFO - #04: mozilla::PresShell::RenderDocument [layout/base/PresShell.cpp:4611]
[task 2018-04-07T09:01:29.367Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.368Z] 09:01:29     INFO - #05: mozilla::image::SVGDrawingCallback::operator() [gfx/src/nsRect.h:52]
[task 2018-04-07T09:01:29.369Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.370Z] 09:01:29     INFO - #06: gfxCallbackDrawable::Draw [gfx/thebes/gfxDrawable.cpp:172]
[task 2018-04-07T09:01:29.371Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.372Z] 09:01:29     INFO - #07: gfxUtils::DrawPixelSnapped [gfx/thebes/gfxUtils.cpp:532]
[task 2018-04-07T09:01:29.373Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.374Z] 09:01:29     INFO - #08: mozilla::image::imgFrame::InitWithDrawable [image/imgFrame.cpp:392]
[task 2018-04-07T09:01:29.375Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.379Z] 09:01:29     INFO - #09: mozilla::image::VectorImage::CreateSurface [image/VectorImage.cpp:1149]
[task 2018-04-07T09:01:29.380Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.381Z] 09:01:29     INFO - #10: mozilla::image::VectorImage::Draw [image/VectorImage.cpp:1031]
[task 2018-04-07T09:01:29.382Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.382Z] 09:01:29     INFO - #11: DrawImageInternal [mfbt/Maybe.h:131]
[task 2018-04-07T09:01:29.383Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.384Z] 09:01:29     INFO - #12: nsLayoutUtils::DrawSingleImage [layout/base/nsLayoutUtils.cpp:7091]
[task 2018-04-07T09:01:29.385Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.386Z] 09:01:29     INFO - #13: nsImageFrame::PaintImage [layout/generic/nsImageFrame.cpp:1785]
[task 2018-04-07T09:01:29.387Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.388Z] 09:01:29     INFO - #14: nsDisplayImage::Paint [layout/generic/nsImageFrame.cpp:1544]
[task 2018-04-07T09:01:29.389Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.390Z] 09:01:29     INFO - #15: mozilla::FrameLayerBuilder::PaintItems [layout/painting/FrameLayerBuilder.cpp:6019]
[task 2018-04-07T09:01:29.391Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.392Z] 09:01:29     INFO - #16: mozilla::FrameLayerBuilder::DrawPaintedLayer [layout/painting/FrameLayerBuilder.cpp:6178]
[task 2018-04-07T09:01:29.392Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.393Z] 09:01:29     INFO - #17: mozilla::layers::ClientPaintedLayer::PaintThebes [gfx/layers/client/ClientPaintedLayer.cpp:166]
[task 2018-04-07T09:01:29.394Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.395Z] 09:01:29     INFO - #18: mozilla::layers::ClientPaintedLayer::RenderLayerWithReadback [gfx/src/nsRegion.h:2234]
[task 2018-04-07T09:01:29.396Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.397Z] 09:01:29     INFO - #19: mozilla::layers::ClientContainerLayer::RenderLayer [gfx/layers/client/ClientContainerLayer.h:60]
[task 2018-04-07T09:01:29.398Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.399Z] 09:01:29     INFO - #20: mozilla::layers::ClientContainerLayer::RenderLayer [gfx/layers/client/ClientContainerLayer.h:60]
[task 2018-04-07T09:01:29.400Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.401Z] 09:01:29     INFO - #21: mozilla::layers::ClientLayerManager::EndTransactionInternal [gfx/layers/client/ClientLayerManager.cpp:359]
[task 2018-04-07T09:01:29.401Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.402Z] 09:01:29     INFO - #22: mozilla::layers::ClientLayerManager::EndTransaction [gfx/layers/client/ClientLayerManager.cpp:424]
[task 2018-04-07T09:01:29.403Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.404Z] 09:01:29     INFO - #23: nsDisplayList::PaintRoot [layout/painting/nsDisplayList.cpp:2753]
[task 2018-04-07T09:01:29.405Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.406Z] 09:01:29     INFO - #24: nsLayoutUtils::PaintFrame [mfbt/RefPtr.h:130]
[task 2018-04-07T09:01:29.406Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.407Z] 09:01:29     INFO - #25: mozilla::PresShell::Paint [layout/base/PresShell.cpp:6313]
[task 2018-04-07T09:01:29.408Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.409Z] 09:01:29     INFO - #26: nsViewManager::ProcessPendingUpdatesPaint [view/nsViewManager.cpp:480]
[task 2018-04-07T09:01:29.409Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.410Z] 09:01:29     INFO - #27: nsViewManager::ProcessPendingUpdatesForView [view/nsViewManager.cpp:412]
[task 2018-04-07T09:01:29.411Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.411Z] 09:01:29     INFO - #28: nsViewManager::ProcessPendingUpdates [view/nsViewManager.cpp:1099]
[task 2018-04-07T09:01:29.412Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.413Z] 09:01:29     INFO - #29: nsRefreshDriver::Tick [layout/base/nsRefreshDriver.cpp:2053]
[task 2018-04-07T09:01:29.414Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.415Z] 09:01:29     INFO - #30: mozilla::RefreshDriverTimer::TickRefreshDrivers [layout/base/nsRefreshDriver.cpp:310]
[task 2018-04-07T09:01:29.416Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.417Z] 09:01:29     INFO - #31: mozilla::RefreshDriverTimer::Tick [layout/base/nsRefreshDriver.cpp:332]
[task 2018-04-07T09:01:29.418Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.419Z] 09:01:29     INFO - #32: mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::TickRefreshDriver [layout/base/nsRefreshDriver.cpp:771]
[task 2018-04-07T09:01:29.420Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.421Z] 09:01:29     INFO - #33: mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::ParentProcessVsyncNotifier::Run [layout/base/nsRefreshDriver.cpp:532]
[task 2018-04-07T09:01:29.423Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.424Z] 09:01:29     INFO - #34: nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:1100]
[task 2018-04-07T09:01:29.425Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.427Z] 09:01:29     INFO - #35: NS_ProcessNextEvent [xpcom/threads/nsThreadUtils.cpp:519]
[task 2018-04-07T09:01:29.428Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.429Z] 09:01:29     INFO - #36: mozilla::ipc::MessagePump::Run [ipc/glue/MessagePump.cpp:98]
[task 2018-04-07T09:01:29.430Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.431Z] 09:01:29     INFO - #37: MessageLoop::RunInternal [ipc/chromium/src/base/message_loop.cc:327]
[task 2018-04-07T09:01:29.432Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.433Z] 09:01:29     INFO - #38: MessageLoop::Run [ipc/chromium/src/base/message_loop.cc:298]
[task 2018-04-07T09:01:29.434Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.436Z] 09:01:29     INFO - #39: nsBaseAppShell::Run [widget/nsBaseAppShell.cpp:159]
[task 2018-04-07T09:01:29.437Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.438Z] 09:01:29     INFO - #40: nsAppStartup::Run [toolkit/components/startup/nsAppStartup.cpp:291]
[task 2018-04-07T09:01:29.439Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.440Z] 09:01:29     INFO - #41: XREMain::XRE_mainRun [toolkit/xre/nsAppRunner.cpp:4772]
[task 2018-04-07T09:01:29.441Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.443Z] 09:01:29     INFO - #42: XREMain::XRE_main [toolkit/xre/nsAppRunner.cpp:4916]
[task 2018-04-07T09:01:29.444Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.445Z] 09:01:29     INFO - #43: XRE_main [toolkit/xre/nsAppRunner.cpp:5009]
[task 2018-04-07T09:01:29.446Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.529Z] 09:01:29     INFO - #44: do_main [browser/app/nsBrowserApp.cpp:231]
[task 2018-04-07T09:01:29.529Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.530Z] 09:01:29     INFO - #45: main [browser/app/nsBrowserApp.cpp:306]
[task 2018-04-07T09:01:29.531Z] 09:01:29     INFO - 
[task 2018-04-07T09:01:29.536Z] 09:01:29     INFO - REFTEST TEST-PASS | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/foreignObject-img-form-theme.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/foreignObject-img-form-theme-ref.html | image comparison, max difference: 0, number of differing pixels: 0
[task 2018-04-07T09:01:29.539Z] 09:01:29     INFO - REFTEST TEST-END | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/foreignObject-img-form-theme.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/foreignObject-img-form-theme-ref.html
[task 2018-04-07T09:01:29.542Z] 09:01:29     INFO - ++DOMWINDOW == 150 (0xc1d58000) [pid = 948] [serial = 5730] [outer = 0xcbe90840]
[task 2018-04-07T09:01:29.543Z] 09:01:29     INFO - REFTEST TEST-UNEXPECTED-FAIL | [u'file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/foreignObject-img-form-theme.html', u'==', u'file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/svg/foreignObject-img-form-theme-ref.html'] | assertion count 1 is more than expected 0 assertions

Comment 4

[Cosmin Sabou [:CosminS]]

After an input from Joel I've gone further with the investigation and seems the above push was not the cause of it. The cause might be this push about Bug 1449631. https://goo.gl/iJCxWy  This has failure rate around 2 fails from 20 jobs.
I didn't retrigger on the two pushes before it because they're were backed out. 

Boris could you please take a look at it?  Thank you.

Comment 5

[Intermittent Failures Robot]

15 failures in 51 pushes (0.294 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-central: 7
* mozilla-inbound: 5
* autoland: 3

Platform breakdown:
* windows7-32: 5
* linux32: 5
* linux64-ccov: 2
* linux64: 2
* windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1451966&startday=2018-04-07&endday=2018-04-07&tree=trunk

Comment 6

[Joel Maher ( :jmaher ) (UTC -8)]

Thanks Cosmin, this does look like the right failure, hopefully :bz can figure out why this is happening.

Comment 7

[Intermittent Failures Robot]

50 failures in 765 pushes (0.065 failures/push) were associated with this bug in the last 7 days. 

This is the #35 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* mozilla-inbound: 20
* mozilla-central: 17
* autoland: 9
* try: 4

Platform breakdown:
* linux32: 17
* windows7-32: 12
* linux64: 9
* linux64-ccov: 8
* windows10-64-ccov: 3
* linux64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1451966&startday=2018-04-02&endday=2018-04-08&tree=trunk

Comment 8

[Boris Zbarsky [:bzbarsky]]

Short story, based on the above stack:

nsViewManager::ProcessPendingUpdatesForView puts a scriptblocker on the stack before calling ProcessPendingUpdatesPaint().  That makes sense.

So we have a scriptblocker in place when we go to draw our SVG image.  And drawing the SVG image does these bits:

  nsRootPresContext::FlushWillPaintObservers calls
  mozilla::ScrollFrameHelper::FireScrollPortEvent calls
  mozilla::EventDispatcher::Dispatch 

inside the SVG document.

We used to not assert here because inside the SVG document calling GetContextForEventHandlers on the event target returned null.  But I took that check out in https://hg.mozilla.org/mozilla-central/rev/1f824c936c25 when I removed GetContextForEventHandlers.

Just using GetOwnerGlobal() and skipping the assert/warning when it returns null is not quite semantically equivalent to what we used to have, because it can return null in situations where GetContextForEventHandlers would have had NS_FAILED(rv) and hence triggered the warning.  This is the case when GetScriptHandlingObject() returns null but hasHadScriptObject is true for a node.  This might also be the case when a DOMEventTargetHelper has mHasOrHasHadOwnerWindow && !mOwnerWindow.

Anyway, in practice this is only being a problem for nodes (in this bug and in bug 1452471), so I am going to just loosen things up for nodes.

Comment 9

[Boris Zbarsky [:bzbarsky]]

Attachment: Don't warn or assert for events firing while !IsSafeToRunScript() inside documents that are never exposed to script

MozReview-Commit-ID: HgvQFJtW9Z6

Comment 10

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

Comment on attachment 8966292 [details] [diff] [review]
Don't warn or assert for events firing while !IsSafeToRunScript() inside documents that are never exposed to script

Sorry that I missed this in the earlier patch.

Comment 11

[Robert Longson [:longsonr]]

there's a typo in the code comment s/restric/restrict/

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/cc9c9128b1f6
Don't warn or assert for events firing while !IsSafeToRunScript() inside documents that are never exposed to script.  r=smaug

Comment 13

[Boris Zbarsky [:bzbarsky]]

> there's a typo in the code comment s/restric/restrict/

Fixed that.  Thank you for catching it!

Comment 14

[Intermittent Failures Robot]

20 failures in 131 pushes (0.153 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 8
* mozilla-central: 6
* mozilla-inbound: 5
* try: 1

Platform breakdown:
* windows7-32: 8
* linux32: 5
* linux64-qr: 2
* linux64-ccov: 2
* linux64: 2
* windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1451966&startday=2018-04-09&endday=2018-04-09&tree=trunk

Comment 15

[Natalia Csoregi [:nataliaCs]]

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

Comment 16

[Intermittent Failures Robot]

24 failures in 792 pushes (0.03 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 10
* mozilla-central: 6
* mozilla-inbound: 5
* try: 3

Platform breakdown:
* windows7-32: 11
* linux32: 6
* linux64-qr: 2
* linux64-ccov: 2
* linux64: 2
* windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1451966&startday=2018-04-09&endday=2018-04-15&tree=trunk