Closed Bug 1667620 Opened 4 years ago Closed 4 years ago

Intermittent pagination/abspos-breaking-004.html == pagination/abspos-breaking-004-ref.html | assertion count 18 is more than expected 12 assertions

Categories

(Core :: Layout, defect, P5)

Product:
Core
Component:
Layout
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
86 Branch
Tracking Flags:
Tracking Status
firefox-esr78 --- unaffected
firefox81 --- unaffected
firefox82 --- unaffected
firefox83 --- wontfix
firefox84 --- wontfix
firefox85 --- wontfix
firefox86 --- fixed

People

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

References

(Regression)

Details

(Keywords: assertion, intermittent-failure, regression, Whiteboard: [stockwell unknown])

Attachments

(1 file)

Bug 1667620: Use a more-permissive "asserts" annotation for reftest abspos-breaking-004.html. (no review, just adjusting test metadata)
48 bytes, text/x-phabricator-request
Details | Review

Filed by: dluca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=316810377&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/N1ImOXa8SbqaVSwYUTJMDQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/N1ImOXa8SbqaVSwYUTJMDQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

INFO - #27: mozilla::ipc::MessageChannel::DispatchAsyncMessage(mozilla::ipc::ActorLifecycleProxy*, IPC::Message const&) [ipc/glue/MessageChannel.cpp:2150]
[task 2020-09-26T19:44:40.470Z] 19:44:40 INFO - #28: mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message&&) [ipc/glue/MessageChannel.cpp:2074]
[task 2020-09-26T19:44:40.471Z] 19:44:40 INFO - #29: mozilla::ipc::MessageChannel::RunMessage(mozilla::ipc::MessageChannel::MessageTask&) [ipc/glue/MessageChannel.cpp:1923]
[task 2020-09-26T19:44:40.471Z] 19:44:40 INFO - #30: mozilla::ipc::MessageChannel::MessageTask::Run() [ipc/glue/MessageChannel.cpp:1955]
[task 2020-09-26T19:44:40.472Z] 19:44:40 INFO - #31: mozilla::RunnableTask::Run() [xpcom/threads/TaskController.cpp:245]
[task 2020-09-26T19:44:40.472Z] 19:44:40 INFO - #32: mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:515]
[task 2020-09-26T19:44:40.473Z] 19:44:40 INFO - #33: mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:373]
[task 2020-09-26T19:44:40.473Z] 19:44:40 INFO - #34: mozilla::TaskController::ProcessPendingMTTask(bool) [xpcom/threads/TaskController.cpp:172]
[task 2020-09-26T19:44:40.476Z] 19:44:40 INFO - #35: mozilla::detail::RunnableFunction<`lambda at /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:87:7'>::Run() [xpcom/threads/nsThreadUtils.h:578]
[task 2020-09-26T19:44:40.477Z] 19:44:40 INFO - #36: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1236]
[task 2020-09-26T19:44:40.477Z] 19:44:40 INFO - #37: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:513]
[task 2020-09-26T19:44:40.478Z] 19:44:40 INFO - #38: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:109]
[task 2020-09-26T19:44:40.478Z] 19:44:40 INFO - #39: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:334]
[task 2020-09-26T19:44:40.478Z] 19:44:40 INFO - #40: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:328]
[task 2020-09-26T19:44:40.478Z] 19:44:40 INFO - #41: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:310]
[task 2020-09-26T19:44:40.478Z] 19:44:40 INFO - #42: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:139]
[task 2020-09-26T19:44:40.479Z] 19:44:40 INFO - #43: nsAppShell::Run() [widget/windows/nsAppShell.cpp:602]
[task 2020-09-26T19:44:40.480Z] 19:44:40 INFO - #44: XRE_RunAppShell() [toolkit/xre/nsEmbedFunctions.cpp:913]
[task 2020-09-26T19:44:40.480Z] 19:44:40 INFO - #45: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:237]
[task 2020-09-26T19:44:40.481Z] 19:44:40 INFO - #46: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:334]
[task 2020-09-26T19:44:40.481Z] 19:44:40 INFO - #47: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:328]
[task 2020-09-26T19:44:40.482Z] 19:44:40 INFO - #48: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:310]
[task 2020-09-26T19:44:40.482Z] 19:44:40 INFO - #49: XRE_InitChildProcess(int, char**, XREChildData const*) [toolkit/xre/nsEmbedFunctions.cpp:748]
[task 2020-09-26T19:44:40.482Z] 19:44:40 INFO - #50: mozilla::BootstrapImpl::XRE_InitChildProcess(int, char**, XREChildData const*) [toolkit/xre/Bootstrap.cpp:67]
[task 2020-09-26T19:44:40.483Z] 19:44:40 INFO - #51: NS_internal_main(int, char**, char**) [browser/app/nsBrowserApp.cpp:304]
[task 2020-09-26T19:44:40.483Z] 19:44:40 INFO - #52: wmain(int, wchar_t**) [toolkit/xre/nsWindowsWMain.cpp:131]
[task 2020-09-26T19:44:40.483Z] 19:44:40 INFO - #53: __scrt_common_main_seh() [/builds/worker/workspace/obj-build/browser/app/f:/dd/vctools/crt/vcstartup/src/startup/exe_common.inl:288]
[task 2020-09-26T19:44:40.484Z] 19:44:40 INFO - #54: BaseThreadInitThunk [C:\windows\system32\kernel32.dll + 0x4ef3c]
[task 2020-09-26T19:44:40.484Z] 19:44:40 INFO - #55: RtlInitializeExceptionChain [C:\windows\SYSTEM32\ntdll.dll + 0x63618]
[task 2020-09-26T19:44:40.485Z] 19:44:40 INFO - #56: RtlInitializeExceptionChain [C:\windows\SYSTEM32\ntdll.dll + 0x635eb]
[task 2020-09-26T19:44:40.485Z] 19:44:40 INFO - REFTEST TEST-UNEXPECTED-FAIL | layout/reftests/pagination/abspos-breaking-004.html == layout/reftests/pagination/abspos-breaking-004-ref.html | assertion count 18 is more than expected 12 assertions
[task 2020-09-26T19:44:40.486Z] 19:44:40 INFO - REFTEST TEST-START | layout/reftests/pagination/abspos-breaking-005.html == layout/reftests/pagination/abspos-breaking-005-ref.html
[task 2020-09-26T19:44:40.486Z] 19:44:40 INFO - REFTEST TEST-LOAD | file:///Z:/task_1601148097/build/tests/reftest/tests/layout/reftests/pagination/abspos-breaking-005.html | 4 / 158 (2%)
[task 2020-09-26T19:44:40.488Z] 19:44:40 INFO - [Child 4296, Main Thread] ###!!! ASSERTION: invalid shrink-to-fit ratio: 'ratio >= 0.0 && ratio < 1.0', file /builds/worker/checkouts/gecko/layout/generic/nsPageContentFrame.cpp, line 89
[task 2020-09-26T19:44:40.489Z] 19:44:40 INFO - #01: nsContainerFrame::ReflowChild(nsIFrame*, nsPresContext*, mozilla::ReflowOutput&, mozilla::ReflowInput const&, int, int, nsIFrame::ReflowChildFlags, nsReflowStatus&, nsOverflowContinuationTracker*) [layout/generic/nsContainerFrame.cpp:1124]
[task 2020-09-26T19:44:40.489Z] 19:44:40 INFO - #02: nsPageFrame::ReflowPageContent(nsPresContext*, mozilla::ReflowInput const&) [layout/generic/nsPageFrame.cpp:142]
[task 2020-09-26T19:44:40.490Z] 19:44:40 INFO - #03: nsPageFrame::Reflow(nsPresContext*, mozilla::ReflowOutput&, mozilla::ReflowInput const&, nsReflowStatus&) [layout/generic/nsPageFrame.cpp:165]
[task 2020-09-26T19:44:40.490Z] 19:44:40 INFO - #04: nsContainerFrame::ReflowChild(nsIFrame*, nsPresContext*, mozilla::ReflowOutput&, mozilla::ReflowInput const&, mozilla::WritingMode const&, mozilla::LogicalPoint const&, nsSize const&, nsIFrame::ReflowChildFlags, nsReflowStatus&, nsOverflowContinuationTracker*) [layout/generic/nsContainerFrame.cpp:1088]
[task 2020-09-26T19:44:40.491Z] 19:44:40 INFO - #05: mozilla::PrintedSheetFrame::Reflow(nsPresContext*, mozilla::ReflowOutput&, mozilla::ReflowInput const&, nsReflowStatus&) [layout/generic/PrintedSheetFrame.cpp:133]
[task 2020-09-26T19:44:40.491Z] 19:44:40 INFO - #06: nsContainerFrame::ReflowChild(nsIFrame*, nsPresContext*, mozilla::ReflowOutput&, mozilla::ReflowInput const&, int, int, nsIFrame::ReflowChildFlags, nsReflowStatus&, nsOverflowContinuationTracker*) [layout/generic/nsContainerFrame.cpp:1124]
[task 2020-09-26T19:44:40.491Z] 19:44:40 INFO - #07: nsPageSequenceFrame::Reflow(nsPresContext*, mozilla::ReflowOutput&, mozilla::ReflowInput const&, nsReflowStatus&) [layout/generic/nsPageSequenceFrame.cpp:280]
[task 2020-09-26T19:44:40.492Z] 19:44:40 INFO - #08: nsContainerFrame::ReflowChild(nsIFrame*, nsPresContext*, mozilla::ReflowOutput&, mozilla::ReflowInput const&, mozilla::WritingMode const&, mozilla::LogicalPoint const&, nsSize const&, nsIFrame::ReflowChildFlags, nsReflowStatus&, nsOverflowContinuationTracker*) [layout/generic/nsContainerFrame.cpp:1088]
[task 2020-09-26T19:44:40.492Z] 19:44:40 INFO - #09: nsHTMLScrollFrame::ReflowScrolledFrame(mozilla::ScrollReflowInput*, bool, bool, mozilla::ReflowOutput*) [layout/generic/nsGfxScrollFrame.cpp:760]
[task 2020-09-26T19:44:40.493Z] 19:44:40 INFO - #10: nsHTMLScrollFrame::ReflowContents(mozilla::ScrollReflowInput*, mozilla::ReflowOutput const&) [layout/generic/nsGfxScrollFrame.cpp:902]
[task 2020-09-26T19:44:40.494Z] 19:44:40 INFO - #11: nsHTMLScrollFrame::Reflow(nsPresContext*, mozilla::ReflowOutput&, mozilla::ReflowInput const&, nsReflowStatus&) [layout/generic/nsGfxScrollFrame.cpp:1280]
[task 2020-09-26T19:44:40.495Z] 19:44:40 INFO - #12: nsContainerFrame::ReflowChild(nsIFrame*, nsPresContext*, mozilla::ReflowOutput&, mozilla::ReflowInput const&, int, int, nsIFrame::ReflowChildFlags, nsReflowStatus&, nsOverflowContinuationTracker*) [layout/generic/nsContainerFrame.cpp:1124]
[task 2020-09-26T19:44:40.495Z] 19:44:40 INFO - #13: mozilla::ViewportFrame::Reflow(nsPresContext*, mozilla::ReflowOutput&, mozilla::ReflowInput const&, nsReflowStatus&) [layout/generic/ViewportFrame.cpp:297]
[task 2020-09-26T19:44:40.496Z] 19:44:40 INFO - #14: mozilla::PresShell::DoReflow(nsIFrame*, bool, mozilla::OverflowChangedTracker*) [layout/base/PresShell.cpp:9629]
[task 2020-09-26T19:44:40.496Z] 19:44:40 INFO - #15: mozilla::PresShell::ProcessReflowCommands(bool) [layout/base/PresShell.cpp:9796]
[task 2020-09-26T19:44:40.497Z] 19:44:40 INFO - #16: mozilla::PresShell::DoFlushPendingNotifications(mozilla::ChangesToFlush) [layout/base/PresShell.cpp:4212]
[task 2020-09-26T19:44:40.497Z] 19:44:40 INFO - #17: nsRefreshDriver::Tick(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp) [layout/base/nsRefreshDriver.cpp:2233]
[task 2020-09-26T19:44:40.497Z] 19:44:40 INFO - #18: mozilla::RefreshDriverTimer::TickRefreshDrivers(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp, nsTArray<RefPtr<nsRefreshDriver> >&) [layout/base/nsRefreshDriver.cpp:352]
[task 2020-09-26T19:44:40.498Z] 19:44:40 INFO - #19: mozilla::RefreshDriverTimer::Tick(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp) [layout/base/nsRefreshDriver.cpp:369]
[task 2020-09-26T19:44:40.498Z] 19:44:40 INFO - #20: mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::TickRefreshDriver(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp) [layout/base/nsRefreshDriver.cpp:746]
[task 2020-09-26T19:44:40.499Z] 19:44:40 INFO - #21: mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::NotifyParentProcessVsync() [layout/base/nsRefreshDriver.cpp:648]
[task 2020-09-26T19:44:40.499Z] 19:44:40 INFO - #22: mozilla::VsyncRefreshDriverTimer::RefreshDriverVsyncObserver::NotifyVsync(mozilla::VsyncEvent const&) [layout/base/nsRefreshDriver.cpp:569]
[task 2020-09-26T19:44:40.500Z] 19:44:40 INFO - #23: mozilla::layout::VsyncChild::RecvNotify(mozilla::VsyncEvent const&) [layout/ipc/VsyncChild.cpp:57]
[task 2020-09-26T19:44:40.500Z] 19:44:40 INFO - #24: mozilla::layout::PVsyncChild::OnMessageReceived(IPC::Message const&) [s3:gecko-generated-sources:dcfb0c5c8cc64a4b8592c33a9bb2c1a430c98ebd009674a59f93629a7c17a7323253973267a429964267d5e17f515a9e0c9f5ab4ceb87eda82e2dd117c395600/ipc/ipdl/PVsyncChild.cpp::187]
[task 2020-09-26T19:44:40.501Z] 19:44:40 INFO - #25: mozilla::ipc::PBackgroundChild::OnMessageReceived(IPC::Message const&) [s3:gecko-generated-sources:00136e3caf26c4b7c1e02c7d7b5c085f78c5c635ada1f4b4ddbb1f6a4ef65fe4154430e47012562c0e0ce77c38fc9103b2b15d160520930d739c0ef793d6930f/ipc/ipdl/PBackgroundChild.cpp::6080]

Botondo: Can you please take a look at this bug?

I think it might be caused by bug 1667594 landing here: https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&selectedTaskRun=N1ImOXa8SbqaVSwYUTJMDQ.0&revision=cb8232ebe212789afead39e7709556cfe534324e

Flags: needinfo?(botond)

Bug 1667594 is a compile-time only change. I believe it could not have caused this intermittent.

I think the more likely explanation is that this is a very low-frequency intermittent (in the 4 days since bug 1667594 has landed, it has only occurred once) and just happened to fail on the bug 1667594 push.

Flags: needinfo?(botond)

Set release status flags based on info from the regressing bug 1667594

status-firefox81: --- → unaffected
status-firefox82: --- → unaffected
status-firefox83: --- → affected
status-firefox-esr78: --- → unaffected

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

There have been 34 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2021-01-05&endday=2021-01-12&tree=trunk&bug=1667620

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=326421015&repo=mozilla-central&lineNumber=15268

Daniel, could you assign this to someone?

Flags: needinfo?(dholbert)
Whiteboard: [stockwell needswork:owner]

Likely needs an assertion-count tweak for the same reason as bug 1685367 comment 4 (a version of https://groups.google.com/g/mozilla.dev.platform/c/VBh6oLm4EbQ/m/dbaJcAe6BgAJ )

I can make that adjustment later today.

Looks like the bug summary (mentioning 12 and 18 as assertion-counts) is a bit out of date.

Currently this test is annotated as asserting 4 times, and the recent failure logs show it asserting 6 times, likely for the reason in the dev.platform post linked above as in bug 1685367.

I'll just bump the assertion count to asserts(4-6).

This test spams the same assertion either 4 or 6 times, with this variation
probably being due to an extra reflow which we sometimes incur due to a
font-fallback task having coincidentally just completed, as described in
https://groups.google.com/g/mozilla.dev.platform/c/VBh6oLm4EbQ/m/dbaJcAe6BgAJ

Previously the test was annotated as asserting exactly 4 times, but now we
need to allow for it to sometimes assert 6 times instead.

Pushed by dholbert@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/2e1cc4238982 Use a more-permissive "asserts" annotation for reftest abspos-breaking-004.html. (no review, just adjusting test metadata)

https://hg.mozilla.org/mozilla-central/rev/2e1cc4238982

Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
status-firefox86: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 86 Branch
Assignee: nobody → dholbert
Flags: needinfo?(dholbert)
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: