Open Bug 1708332 Opened 4 years ago Updated 5 months ago

Intermittent docshell/test/mochitest/test_bug529119-1.html | assertion count 2 is more than expected 0 assertions | ASSERTION: should have done initial reflow by now: 'mDidInitialize', file /builds/worker/checkouts/gecko/layout/base/PresShell.cpp:3515

Categories

(Core :: Layout, defect, P5)

Product:
Core
Component:
Layout
Type:
defect

Tracking

()

Status:
REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: assertion, intermittent-failure)

Attachments

(2 files)

Debug log from mochitest comm/calendar/test/browser/browser_todayPane_visibility.js
500.97 KB, text/plain
Details
The patch to obtain the dump in the attached log.
6.55 KB, text/plain
Details

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=338081176&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/fMaZae_pQEORKQbLEyj3OQ/runs/0/artifacts/public/logs/live_backing.log

[task 2021-04-28T22:32:12.719Z] 22:32:12     INFO - TEST-START | docshell/test/mochitest/test_bug529119-1.html
[task 2021-04-28T22:32:13.213Z] 22:32:13     INFO - GECKO(2300) | [Child 9124, Main Thread] WARNING: '!tsi', file /builds/worker/checkouts/gecko/dom/base/Document.cpp:1667
[task 2021-04-28T22:32:13.243Z] 22:32:13     INFO - GECKO(2300) | [Child 9124, Main Thread] WARNING: Trying to set focus to a node from a wrong document: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowInner.cpp:4355
[task 2021-04-28T22:32:13.243Z] 22:32:13     INFO - GECKO(2300) | [Child 9124, Main Thread] ###!!! ASSERTION: should have done initial reflow by now: 'mDidInitialize', file /builds/worker/checkouts/gecko/layout/base/PresShell.cpp:3515
[task 2021-04-28T22:32:13.325Z] 22:32:13     INFO -  Initializing stack-fixing for the first stack frame, this may take a while...
[task 2021-04-28T22:32:22.812Z] 22:32:22     INFO - GECKO(2300) | #01: NS_DebugBreak(unsigned int, char const*, char const*, char const*, int) [xpcom/base/nsDebugImpl.cpp:431]
[task 2021-04-28T22:32:22.812Z] 22:32:22     INFO - GECKO(2300) | #02: mozilla::PresShell::ScrollContentIntoView(nsIContent*, mozilla::ScrollAxis, mozilla::ScrollAxis, mozilla::ScrollFlags) [layout/base/PresShell.cpp:3517]
[task 2021-04-28T22:32:22.812Z] 22:32:22     INFO - GECKO(2300) | #03: nsFocusManager::ScrollIntoView(mozilla::PresShell*, nsIContent*, unsigned int) [dom/base/nsFocusManager.cpp:2820]
[task 2021-04-28T22:32:22.814Z] 22:32:22     INFO - GECKO(2300) | #04: nsFocusManager::Focus(nsPIDOMWindowOuter*, mozilla::dom::Element*, unsigned int, bool, bool, bool, bool, unsigned long long, mozilla::Maybe<nsFocusManager::BlurredElementInfo> const&) [dom/base/nsFocusManager.cpp:2572]
[task 2021-04-28T22:32:22.814Z] 22:32:22     INFO - GECKO(2300) | #05: nsFocusManager::SetFocusInner(mozilla::dom::Element*, int, bool, bool, unsigned long long) [dom/base/nsFocusManager.cpp:1724]
[task 2021-04-28T22:32:22.814Z] 22:32:22     INFO - GECKO(2300) | #06: nsFocusManager::SetFocus(mozilla::dom::Element*, unsigned int) [dom/base/nsFocusManager.cpp:494]
[task 2021-04-28T22:32:22.815Z] 22:32:22     INFO - GECKO(2300) | #07: mozilla::dom::Element::Focus(mozilla::dom::FocusOptions const&, const mozilla::dom::CallerType, mozilla::ErrorResult&) [dom/base/Element.cpp:462]
[task 2021-04-28T22:32:22.815Z] 22:32:22     INFO - GECKO(2300) | #08: mozilla::dom::nsAutoFocusEvent::Run() [dom/base/Document.cpp:12453]
[task 2021-04-28T22:32:22.815Z] 22:32:22     INFO - GECKO(2300) | #09: mozilla::RunnableTask::Run() [xpcom/threads/TaskController.cpp:474]
[task 2021-04-28T22:32:22.815Z] 22:32:22     INFO - GECKO(2300) | #10: mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:757]
[task 2021-04-28T22:32:22.815Z] 22:32:22     INFO - GECKO(2300) | #11: mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:612]
[task 2021-04-28T22:32:22.816Z] 22:32:22     INFO - GECKO(2300) | #12: mozilla::TaskController::ProcessPendingMTTask(bool) [xpcom/threads/TaskController.cpp:396]
[task 2021-04-28T22:32:22.818Z] 22:32:22     INFO - GECKO(2300) | #13: mozilla::detail::RunnableFunction<`lambda at /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:135:7'>::Run() [xpcom/threads/nsThreadUtils.h:535]
[task 2021-04-28T22:32:22.818Z] 22:32:22     INFO - GECKO(2300) | #14: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1163]
[task 2021-04-28T22:32:22.818Z] 22:32:22     INFO - GECKO(2300) | #15: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:548]
[task 2021-04-28T22:32:22.818Z] 22:32:22     INFO - GECKO(2300) | #16: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:85]
[task 2021-04-28T22:32:22.818Z] 22:32:22     INFO - GECKO(2300) | #17: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:329]
[task 2021-04-28T22:32:22.819Z] 22:32:22     INFO - GECKO(2300) | #18: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:311]
[task 2021-04-28T22:32:22.819Z] 22:32:22     INFO - GECKO(2300) | #19: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:139]
[task 2021-04-28T22:32:22.819Z] 22:32:22     INFO - GECKO(2300) | #20: nsAppShell::Run() [widget/windows/nsAppShell.cpp:603]
[task 2021-04-28T22:32:22.821Z] 22:32:22     INFO - GECKO(2300) | #21: XRE_RunAppShell() [toolkit/xre/nsEmbedFunctions.cpp:906]
[task 2021-04-28T22:32:22.821Z] 22:32:22     INFO - GECKO(2300) | #22: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:235]
[task 2021-04-28T22:32:22.821Z] 22:32:22     INFO - GECKO(2300) | #23: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:329]
[task 2021-04-28T22:32:22.821Z] 22:32:22     INFO - GECKO(2300) | #24: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:311]
[task 2021-04-28T22:32:22.821Z] 22:32:22     INFO - GECKO(2300) | #25: XRE_InitChildProcess(int, char**, XREChildData const*) [toolkit/xre/nsEmbedFunctions.cpp:742]
[task 2021-04-28T22:32:22.872Z] 22:32:22     INFO - GECKO(2300) | #26: NS_internal_main(int, char**, char**) [browser/app/nsBrowserApp.cpp:309]
[task 2021-04-28T22:32:22.872Z] 22:32:22     INFO - GECKO(2300) | #27: wmain(int, wchar_t**) [toolkit/xre/nsWindowsWMain.cpp:131]
[task 2021-04-28T22:32:22.872Z] 22:32:22     INFO - GECKO(2300) | #28: __scrt_common_main_seh() [/builds/worker/workspace/obj-build/browser/app/f:/dd/vctools/crt/vcstartup/src/startup/exe_common.inl:288]
[task 2021-04-28T22:32:22.877Z] 22:32:22     INFO -  fix-stacks: error: failed to read debug info file `wkernel32.pdb` for `C:\windows\System32\KERNEL32.DLL`
[task 2021-04-28T22:32:22.877Z] 22:32:22     INFO -  fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs
[task 2021-04-28T22:32:22.877Z] 22:32:22     INFO -  fix-stacks: The system cannot find the file specified. (os error 2)
[task 2021-04-28T22:32:22.877Z] 22:32:22     INFO - GECKO(2300) | #29: BaseThreadInitThunk [C:\windows\System32\KERNEL32.DLL + 0x13034]
[task 2021-04-28T22:32:22.882Z] 22:32:22     INFO -  fix-stacks: error: failed to read debug info file `wntdll.pdb` for `C:\windows\SYSTEM32\ntdll.dll`
[task 2021-04-28T22:32:22.882Z] 22:32:22     INFO -  fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs
[task 2021-04-28T22:32:22.883Z] 22:32:22     INFO -  fix-stacks: The system cannot find the file specified. (os error 2)
[task 2021-04-28T22:32:22.883Z] 22:32:22     INFO - GECKO(2300) | #30: RtlUserThreadStart [C:\windows\SYSTEM32\ntdll.dll + 0x71461]
[task 2021-04-28T22:32:22.883Z] 22:32:22     INFO - GECKO(2300) | [Child 9124, Main Thread] ###!!! ASSERTION: should have done initial reflow by now: 'mDidInitialize', file /builds/worker/checkouts/gecko/layout/base/PresShell.cpp:3552
[task 2021-04-28T22:32:22.884Z] 22:32:22     INFO - GECKO(2300) | #01: NS_DebugBreak(unsigned int, char const*, char const*, char const*, int) [xpcom/base/nsDebugImpl.cpp:431]
[task 2021-04-28T22:32:22.884Z] 22:32:22     INFO - GECKO(2300) | #02: mozilla::PresShell::DoScrollContentIntoView() [layout/base/PresShell.cpp:3554]
[task 2021-04-28T22:32:22.884Z] 22:32:22     INFO - GECKO(2300) | #03: mozilla::PresShell::ScrollContentIntoView(nsIContent*, mozilla::ScrollAxis, mozilla::ScrollAxis, mozilla::ScrollFlags) [layout/base/PresShell.cpp:3549]
[task 2021-04-28T22:32:22.885Z] 22:32:22     INFO - GECKO(2300) | #04: nsFocusManager::ScrollIntoView(mozilla::PresShell*, nsIContent*, unsigned int) [dom/base/nsFocusManager.cpp:2820]
[task 2021-04-28T22:32:22.885Z] 22:32:22     INFO - GECKO(2300) | #05: nsFocusManager::Focus(nsPIDOMWindowOuter*, mozilla::dom::Element*, unsigned int, bool, bool, bool, bool, unsigned long long, mozilla::Maybe<nsFocusManager::BlurredElementInfo> const&) [dom/base/nsFocusManager.cpp:2572]
[task 2021-04-28T22:32:22.885Z] 22:32:22     INFO - GECKO(2300) | #06: nsFocusManager::SetFocusInner(mozilla::dom::Element*, int, bool, bool, unsigned long long) [dom/base/nsFocusManager.cpp:1724]
[task 2021-04-28T22:32:22.886Z] 22:32:22     INFO - GECKO(2300) | #07: nsFocusManager::SetFocus(mozilla::dom::Element*, unsigned int) [dom/base/nsFocusManager.cpp:494]
[task 2021-04-28T22:32:22.886Z] 22:32:22     INFO - GECKO(2300) | #08: mozilla::dom::Element::Focus(mozilla::dom::FocusOptions const&, const mozilla::dom::CallerType, mozilla::ErrorResult&) [dom/base/Element.cpp:462]
[task 2021-04-28T22:32:22.886Z] 22:32:22     INFO - GECKO(2300) | #09: mozilla::dom::nsAutoFocusEvent::Run() [dom/base/Document.cpp:12453]
[task 2021-04-28T22:32:22.887Z] 22:32:22     INFO - GECKO(2300) | #10: mozilla::RunnableTask::Run() [xpcom/threads/TaskController.cpp:474]
[task 2021-04-28T22:32:22.887Z] 22:32:22     INFO - GECKO(2300) | #11: mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:757]
[task 2021-04-28T22:32:22.887Z] 22:32:22     INFO - GECKO(2300) | #12: mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:612]
[task 2021-04-28T22:32:22.888Z] 22:32:22     INFO - GECKO(2300) | #13: mozilla::TaskController::ProcessPendingMTTask(bool) [xpcom/threads/TaskController.cpp:396]
[task 2021-04-28T22:32:22.888Z] 22:32:22     INFO - GECKO(2300) | #14: mozilla::detail::RunnableFunction<`lambda at /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:135:7'>::Run() [xpcom/threads/nsThreadUtils.h:535]
[task 2021-04-28T22:32:22.889Z] 22:32:22     INFO - GECKO(2300) | #15: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1163]
[task 2021-04-28T22:32:22.889Z] 22:32:22     INFO - GECKO(2300) | #16: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:548]
[task 2021-04-28T22:32:22.890Z] 22:32:22     INFO - GECKO(2300) | #17: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:85]
[task 2021-04-28T22:32:22.890Z] 22:32:22     INFO - GECKO(2300) | #18: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:329]
[task 2021-04-28T22:32:22.890Z] 22:32:22     INFO - GECKO(2300) | #19: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:311]
[task 2021-04-28T22:32:22.891Z] 22:32:22     INFO - GECKO(2300) | #20: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:139]
[task 2021-04-28T22:32:22.891Z] 22:32:22     INFO - GECKO(2300) | #21: nsAppShell::Run() [widget/windows/nsAppShell.cpp:603]
[task 2021-04-28T22:32:22.891Z] 22:32:22     INFO - GECKO(2300) | #22: XRE_RunAppShell() [toolkit/xre/nsEmbedFunctions.cpp:906]
[task 2021-04-28T22:32:22.892Z] 22:32:22     INFO - GECKO(2300) | #23: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:235]
[task 2021-04-28T22:32:22.892Z] 22:32:22     INFO - GECKO(2300) | #24: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:329]
[task 2021-04-28T22:32:22.892Z] 22:32:22     INFO - GECKO(2300) | #25: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:311]
[task 2021-04-28T22:32:22.892Z] 22:32:22     INFO - GECKO(2300) | #26: XRE_InitChildProcess(int, char**, XREChildData const*) [toolkit/xre/nsEmbedFunctions.cpp:742]
[task 2021-04-28T22:32:22.892Z] 22:32:22     INFO - GECKO(2300) | #27: NS_internal_main(int, char**, char**) [browser/app/nsBrowserApp.cpp:309]
[task 2021-04-28T22:32:22.893Z] 22:32:22     INFO - GECKO(2300) | #28: wmain(int, wchar_t**) [toolkit/xre/nsWindowsWMain.cpp:131]
[task 2021-04-28T22:32:22.893Z] 22:32:22     INFO - GECKO(2300) | #29: __scrt_common_main_seh() [/builds/worker/workspace/obj-build/browser/app/f:/dd/vctools/crt/vcstartup/src/startup/exe_common.inl:288]
[task 2021-04-28T22:32:22.893Z] 22:32:22     INFO - GECKO(2300) | #30: BaseThreadInitThunk [C:\windows\System32\KERNEL32.DLL + 0x13034]
[task 2021-04-28T22:32:22.893Z] 22:32:22     INFO - GECKO(2300) | #31: RtlUserThreadStart [C:\windows\SYSTEM32\ntdll.dll + 0x71461]
[task 2021-04-28T22:32:22.893Z] 22:32:22     INFO - GECKO(2300) | [Child 9124, Main Thread] WARNING: NS_ENSURE_TRUE(inner) failed: file /builds/worker/checkouts/gecko/toolkit/components/satchel/nsFormFillController.cpp:847
[task 2021-04-28T22:32:22.894Z] 22:32:22     INFO - GECKO(2300) | [Child 9124, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:181
[task 2021-04-28T22:32:22.894Z] 22:32:22     INFO - GECKO(2300) | [Child 9124, Main Thread] WARNING: '!tsi', file /builds/worker/checkouts/gecko/dom/base/Document.cpp:1667
[task 2021-04-28T22:32:22.894Z] 22:32:22     INFO - GECKO(2300) | MEMORY STAT | vsize 2104199MB | vsizeMaxContiguous 66121754MB | residentFast 167MB | heapAllocated 24MB
[task 2021-04-28T22:32:22.894Z] 22:32:22     INFO - GECKO(2300) | [Child 9124, Main Thread] WARNING: NS_ENSURE_TRUE(inner) failed: file /builds/worker/checkouts/gecko/toolkit/components/satchel/nsFormFillController.cpp:847
[task 2021-04-28T22:32:22.894Z] 22:32:22     INFO - GECKO(2300) | [Child 9124, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/caps/BasePrincipal.cpp:1349
[task 2021-04-28T22:32:22.895Z] 22:32:22     INFO - TEST-OK | docshell/test/mochitest/test_bug529119-1.html | took 1471ms
[task 2021-04-28T22:32:22.895Z] 22:32:22     INFO - TEST-UNEXPECTED-FAIL | docshell/test/mochitest/test_bug529119-1.html | assertion count 2 is more than expected 0 assertions
[task 2021-04-28T22:32:22.895Z] 22:32:22     INFO - TEST-START | docshell/test/mochitest/test_bug529119-2.html```

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

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=369710014&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

I see many of the assertions in my local mochitest of TB (comm-central) too.
Testing under Debian GNU/Linux.

This hampers the analysis of OTHER legitimate bugs. :-(
There are simply too many of them: In the latest log, I count 122 of them. (!).

egrep "(should have done)" /FF-NEW/log1402*.txt  | wc
  122    2196   24278

Now the interesting thing about this assertion is that it seems to have been dormant for a while as far as TB tests are concerned.
My not so scientific check is as follows.
I keep local logs for comparison and they are serially numbered.

ishikawa@ip030:/NREF-COMM-CENTRAL/mozilla/comm$ egrep -l "(should have done)" /FF-NEW/*.txt  
/FF-NEW/log1026-mozmill-fixedstack.txt
/FF-NEW/log1026-mozmill.txt
/FF-NEW/log1028-mozmill.txt      <--- Note the jump of serial number here
/FF-NEW/log1314-mochitest.txt   <--- and the next line.
/FF-NEW/log1315-mochitest.txt
/FF-NEW/log1316-mochitest.txt
/FF-NEW/log1317-mochitest.txt
/FF-NEW/log1322-mochitest.txt
/FF-NEW/log1323-mochitest-pod_calloc.txt
/FF-NEW/log1324-mochitest-pod_calloc-different-timeout.txt
/FF-NEW/log1325-mochitest-pod_calloc-different-timeout.txt
/FF-NEW/log1327-mochitest-memory.txt
/FF-NEW/log1327-mochitest.txt
/FF-NEW/log1331-mochitest-memory.txt
/FF-NEW/log1333-mochitest-memory.txt
/FF-NEW/log1334-mochitest-memory.txt
/FF-NEW/log1335-mochitest.txt
/FF-NEW/log1339-mochitest.txt
/FF-NEW/log1341-mochitest.txt
/FF-NEW/log1343-mochitest.txt
/FF-NEW/log1345-mochitest.txt
/FF-NEW/log1347-mochitest.txt
/FF-NEW/log1348-mochitest.txt
/FF-NEW/log1350-mochitest.txt
/FF-NEW/log1351-mochitest.txt
/FF-NEW/log1352-mochitest.txt
/FF-NEW/log1353-mochitest.txt
/FF-NEW/log1356-mochitest.txt
/FF-NEW/log1359-mochitest.txt
/FF-NEW/log13610-mochitest.txt
/FF-NEW/log1363-mochitest.txt
/FF-NEW/log1364-mochitest.txt
/FF-NEW/log1365-mochitest.txt
/FF-NEW/log1366-mochitest.txt
/FF-NEW/log1369-mochitest.txt
/FF-NEW/log1374-mochitest.txt
/FF-NEW/log1375-mochitest.txt
/FF-NEW/log1376-mochitest.txt
/FF-NEW/log1377-mochitest.txt
/FF-NEW/log1379-mochites.txt
/FF-NEW/log1380-asan-mochites.txt
/FF-NEW/log1381-asan-xpcshell.txt
/FF-NEW/log1383-mochitest.txt
/FF-NEW/log1384-mochitest.txt
/FF-NEW/log1387-mochitest.txt
/FF-NEW/log1388-mochitest.txt
/FF-NEW/log1389-mochitest.txt
/FF-NEW/log1391-mochitest.txt
/FF-NEW/log1392-mochitest-12.txt
/FF-NEW/log1395-mochitest-19.txt
/FF-NEW/log1396-mochitest-21.txt
/FF-NEW/log1397-mochitest-13.txt
/FF-NEW/log1401-mochitest-20.txt
/FF-NEW/log1402-mochitest-13.txt
ishikawa@ip030:/NREF-COMM-CENTRAL/mozilla/comm$

Note this part.

/FF-NEW/log1028-mozmill.txt      <--- Note the jump of serial number here
/FF-NEW/log1314-mochitest.txt   <--- and the next line.

Well, log1028-mozmill.txt has a timestamp of July 13, 2019.
log1314-mochitest.txt has a timestamp of June 2, 2021.
Note that there were time periods when I was focused on running tests under valgrind and met difficulties and did not
run full tests quite often.
Still, I bet something masked the warning for quite a while.
It definitely came back sometime before June last year [and it jived with the date of "opening" of this bugzilla entry.] and since then it shows up more or less constantly and quite often in each mochitest run. (Note that my serial numbering of local log files is used by xpcshell test, too.
That is why the above mochitest log files lately are not necessarily consecutive.)

Assertions fail tests and so I am not able to see if my local patches break tests.
The cause of these assertions need to be eliminated for healthy testing, especially for TB since there are simply too many of them :-(, IMHO.

I wonder if there is a simple wait and/or other time-related interlocking is missing.

BTW, this is not only my local TB mochitest, etc. but people's try-comm-central test.
See, for example, BenC's job:
https://treeherder.mozilla.org/jobs?repo=try-comm-central&selectedTaskRun=NWM7FPeFRPqV8FRt_quyng.0&revision=347d4339dba95e846d82315f394ddd7184f9cf1d
bct2:
https://firefoxci.taskcluster-artifacts.net/NWM7FPeFRPqV8FRt_quyng/0/public/logs/live_backing.log

So, it's not only me, but everybody's TB test log on tryserver (debug version test, that is.).

I don't think we can do reasonable scroll before redrawing is done.

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

Status: REOPENED → RESOLVED
Closed: 3 years ago → 2 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=381027491&repo=mozilla-central

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago → 2 years ago
Resolution: --- → DUPLICATE

I have no idea why it was closed as RESOLVED.

In debug build, the assertion is all the time.
Please see, say,
https://treeherder.mozilla.org/logviewer?job_id=419245297&repo=try-comm-central

Now I see.
Maybe for firefox, this has been resolved(?)

But for Thunderbird, the assertion is hit so many times during mochitest of DEBUG version, and actually it is so noisy to look at other valid bugs. :-(

Should we split this bug and file a new one for THUNDERBIRD?

OK, I found an anomaly.

I looked at the code and found that |mDdInitialize| is set to true in |PressShell::Initailize()|.

So I searched where this function is called called. I searched by searchfox, I typed in "PressShell::Initialize".

Lo and behold, there are differences between the search results between M-C and C-C (!)

Note the different # of hits.

(1) Search in M-C

Definitions (mozilla::PresShell::Initialize) (1 lines across 1 files)
	layout/base/PresShell.cpp
1760	nsresult PresShell::Initialize() {
 
▼
	
Uses (mozilla::PresShell::Initialize) (8 lines across 8 files)
	dom/base/nsContentSink.cpp
543	nsresult rv = presShell->Initialize(); // found in nsContentSink::StartLayout
	dom/base/nsGlobalWindowOuter.cpp
1800	presShell->Initialize(); // found in nsGlobalWindowOuter::SetInitialPrincipal
	dom/html/MediaDocument.cpp
234	nsresult rv = presShell->Initialize(); // found in mozilla::dom::MediaDocument::StartLayout
	dom/prototype/PrototypeDocumentContentSink.cpp
702	nsresult rv = presShell->Initialize(); // found in mozilla::dom::PrototypeDocumentContentSink::StartLayout
	gfx/thebes/gfxSVGGlyphs.cpp
159	rv = presShell->Initialize(); // found in gfxSVGGlyphsDocument::SetupPresentation
	layout/base/PresShell.cpp
10305	presShell->Initialize(); // found in mozilla::PresShell::VerifyIncrementalReflow
	layout/base/nsDocumentViewer.cpp
754	presShell->Initialize(); // found in nsDocumentViewer::InitPresentationStuff
	layout/printing/nsPrintJob.cpp
1368	MOZ_TRY(aPO->mPresShell->Initialize()); // found in nsPrintJob::ReflowPrintObject
 
▼
	
Declarations (mozilla::PresShell::Initialize) (1 lines across 1 files)
	layout/base/PresShell.h
344	MOZ_CAN_RUN_SCRIPT_BOUNDARY nsresult Initialize(); // found in mozilla::PresShell

        ...

(2) Search in C-C

Number of results: 6 (maximum is around 4000)
 
§	
Core code (5 lines across 3 files)
 
▼
	
Textual Occurrences (5 lines across 3 files)
	mozilla/accessible/docs/DocumentAccessibilityLifecycle.md
8	1. The layout [PresShell gets initialized (PresShell::Initialize)](https://searchfox.org/mozilla-central/rev/4e87b5392eafe1f1d49017e76f7317b06ec0b1d8/layout/base/PresShell.cpp#1820).
	mozilla/layout/base/PresShell.cpp
1760	nsresult PresShell::Initialize() {
1770	MOZ_LOG(gLog, LogLevel::Debug, ("PresShell::Initialize this=%p", this));
1794	printf("*** PresShell::Initialize (this=%p, url='%s')\n", (void*)this,
	mozilla/layout/base/nsDocumentViewer.cpp
2093	// its PresShell::Initialize call can cause scripts to run and therefore
 
§	
Test files (1 lines across 1 files)
 
▼
	
Textual Occurrences (1 lines across 1 files)
	mozilla/layout/generic/test/file_scroll_position_restore_no_bfcache.html
24	<!-- This is important as it delays layout, so that stuff goes through PresShell::Initialize under `mDelayedLayoutStart` instead of ContentAppended -->

Huh? The initialization is NOT called in C-C TB?

I checked that the lines found in M-C search are present in C-C files exactly at the same lines.

That led me to think for a while.
Can it be that there is a typo (maybe missing class attribute or something) somewhere that screws up the class hierarchy and
PressShell::Initialize() is not automatically called in C-C TB?

If not, I would think SearchFox will find the same lines in both M-C and C-C IMHO.

Status: RESOLVED → REOPENED
No longer duplicate of bug: 1777074
Resolution: DUPLICATE → ---

(In reply to ISHIKAWA, Chiaki from comment #16)

OK, I found an anomaly.

I looked at the code and found that |mDdInitialize| is set to true in |PressShell::Initailize()|.

So I searched where this function is called called. I searched by searchfox, I typed in "PressShell::Initialize".

Lo and behold, there are differences between the search results between M-C and C-C (!)

Note the different # of hits.

(1) Search in M-C

... [omission] ...

Huh? The initialization is NOT called in C-C TB?

I checked that the lines found in M-C search are present in C-C files exactly at the same lines.

That led me to think for a while.
Can it be that there is a typo (maybe missing class attribute or something) somewhere that screws up the class hierarchy and
PressShell::Initialize() is not automatically called in C-C TB?

If not, I would think SearchFox will find the same lines in both M-C and C-C IMHO.

Either that or searchfox does not have proper parse information in C-C so it cannot search for meaningful hits based on class hierarchy in C-C.
I have noticed that M-C search result has "Uses (mozilla::PresShell::Initialize)" whereas C-C search result has only "Textual Occurrences" which M-C search also has.

I have inserted some fprintf statements to figure out which allocation of PresShell::PresShell caused the assertion in DEBUG build.
I will upload the log from running a single target, comm/calendar/test/browser/browser_todayPane_visibility.js in C-C TB's mochitest.

Looking at the allocation PresShell::PresShell() and
initialization PresShell::Initialize(),
I notice some async nature of the call to Initialize() after the allocation.
Also, there seem to be several PressShell() calls that are NOT
followed by Initialization(), not only the one that triggered the assertion.

The assertion error is reported after the 107 or 108th call of
PresShell:PresShell() and so I dump the stacktrace from PresShell:PresShell()
by using NS_ASSERTION() from 100th call of it.

From the local log, I found that the assertion, "###!!! ASSERTION: should have done initial reflow by now: 'mDidInitialize', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/PresShell.cpp:3583", is triggered for |this| (PresShell::PresShell this=0x555f3925cdd0)
and this PresShell was allocated inside Document.cpp.

PresShell::Init() is called for this allocation, but
PresShell::Initialize() is not.
Before the "###!!! ASSERTION: should have ..." is hit, there were some debug messages I inserted in the code. I wonder if some errors in the code flow precluded the call to PresShell::Initalize().

00:55.34 GECKO(114273) PresShell::Init(...) this=0x555f3925cdd0
00:55.34 GECKO(114273) {debug} SetSpec failed. : aSpec=messenger/treeView.ftl
00:55.34 GECKO(114273) {debug} SetSpec failed. : aSpec=messenger/treeView.ftl
00:55.34 GECKO(114273) {debug} SetSpec failed. : aSpec=messenger/addressbook/aboutAddressBook.ftl
00:55.34 GECKO(114273) {debug} SetSpec failed. : aSpec=messenger/addressbook/aboutAddressBook.ftl
00:55.34 GECKO(114273) {debug} SetSpec failed. : aSpec=messenger/preferences/preferences.ftl
00:55.34 GECKO(114273) {debug} SetSpec failed. : aSpec=messenger/preferences/preferences.ftl
00:55.34 GECKO(114273) {debug} SetSpec failed. : aSpec=messenger/appmenu.ftl
00:55.34 GECKO(114273) {debug} SetSpec failed. : aSpec=messenger/appmenu.ftl
00:55.34 GECKO(114273) ScrollContentIntoView(): this = 0x555f3925cdd0
00:55.34 GECKO(114273) [Parent 114273, Main Thread] ###!!! ASSERTION: should have done initial reflow by now: 'mDidInitialize', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/PresShell.cpp:3586
00:55.34 GECKO(114273) #01: NS_DebugBreak.cold (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsDebugImpl.cpp:493)

I don't know why the particular allocation caused the issue.
Can it be the async race? (That is scroll routine is called BEFORE initialize?)
Or can it be that this allocation PresShell needs to be handled differently from other allocaition.

I am not familiar with the code itself, and so I shall leave it to someone in the know.

I wonder, though, whether we should set mDidInitialize or some such in
PresShell::Init() routine. Probably not, but since there ARE allocations that do not get followed by Initialize(), maybe we need to think about it.

From that stacktrace of the allocation which later caused the assertion. This is allocated in Document.cpp:

00:55.15 GECKO(114273) #02: mozilla::PresShell::PresShell(mozilla::dom::Document*) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/PresShell.cpp:806)
00:55.15 GECKO(114273) #03: mozilla::dom::Document::CreatePresShell(nsPresContext*, nsViewManager*) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/dom/base/Document.cpp:6971)
00:55.15 GECKO(114273) #04: nsDocumentViewer::InitPresentationStuff(bool) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/nsDocumentViewer.cpp:678)
00:55.20 GECKO(114273) #05: nsDocumentViewer::InitInternal(nsIWidget*, nsISupports*, mozilla::dom::WindowGlobalChild*, mozilla::gfx::IntRectTyped<mozilla::gfx::UnknownUnits> const&, bool, bool, bool) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/nsDocumentViewer.cpp:909)
00:55.20 GECKO(114273) #06: nsDocumentViewer::Init(nsIWidget*, mozilla::gfx::IntRectTyped<mozilla::gfx::UnknownUnits> const&, mozilla::dom::WindowGlobalChild*) (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/nsDocumentViewer.cpp:676)
00:55.20 GECKO(114273) #07: nsDocShell::SetupNewViewer(nsIContentViewer*, mozilla::dom::WindowGlobalChild*) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/docshell/base/nsDocShell.cpp:8175)
00:55.20 GECKO(114273) #08: nsDocShell::Embed(nsIContentViewer*, mozilla::dom::WindowGlobalChild*, bool, bool, nsIRequest*, nsIURI*) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/docshell/base/nsDocShell.cpp:5632)
00:55.20 GECKO(114273) #09: nsDocShell::CreateContentViewer(nsTSubstring<char> const&, nsIRequest*, nsIStreamListener**) [clone .part.0] [clone .constprop.0] [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/docshell/base/nsDocShell.cpp:7997)
00:55.20 GECKO(114273) #10: nsDSURIContentListener::DoContent(nsTSubstring<char> const&, bool, nsIRequest*, nsIStreamListener**, bool*) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/docshell/base/nsDSURIContentListener.cpp:168)
00:55.20 GECKO(114273) #11: nsDocumentOpenInfo::TryContentListener(nsIURIContentListener*, nsIChannel*) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/uriloader/base/nsURILoader.cpp:635)
00:55.21 GECKO(114273) #12: nsDocumentOpenInfo::DispatchContent(nsIRequest*) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/uriloader/base/nsURILoader.cpp:330)
00:55.21 GECKO(114273) #13: nsDocumentOpenInfo::OnStartRequest(nsIRequest*) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/uriloader/base/nsURILoader.cpp:159)
00:55.21 GECKO(114273) #14: mozilla::net::ForwardStreamListenerFunctions(nsTArray<mozilla::Variant<mozilla::net::OnStartRequestParams, mozilla::net::OnDataAvailableParams, mozilla::net::OnStopRequestParams, mozilla::net::OnAfterLastPartParams> >&, nsIStreamListener*) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/netwerk/ipc/NeckoCommon.cpp:21)
00:55.21 GECKO(114273) #15: mozilla::net::DocumentLoadListener::ResumeSuspendedChannel(nsIStreamListener*) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/netwerk/ipc/DocumentLoadListener.cpp:1447)
00:55.21 GECKO(114273) #16: mozilla::net::DocumentLoadListener::FinishReplacementChannelSetup(nsresult) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/netwerk/ipc/DocumentLoadListener.cpp:1356)
00:55.21 GECKO(114273) #17: mozilla::net::DocumentLoadListener::RedirectToRealChannelFinished(nsresult) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/netwerk/ipc/DocumentLoadListener.cpp:1304)
00:55.21 GECKO(114273) #18: mozilla::MozPromise<nsresult, mozilla::ipc::ResponseRejectReason, true>::ThenValue<mozilla::net::DocumentLoadListener::TriggerRedirectToRealChannel(mozilla::Maybe<mozilla::dom::ContentParent*> const&, nsTArray<mozilla::net::StreamFilterRequest>)::{lambda(nsresult const&)#1}, mozilla::net::DocumentLoadListener::TriggerRedirectToRealChannel(mozilla::Maybe<mozilla::dom::ContentParent*> const&, nsTArray<mozilla::net::StreamFilterRequest>)::{lambda(mozilla::ipc::ResponseRejectReason)#2}>::DoResolveOrRejectInternal(mozilla::MozPromise<nsresult, mozilla::ipc::ResponseRejectReason, true>::ResolveOrRejectValue&) [clone .cold] (/NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/mozilla/MozPromise.h:654)
00:55.33 GECKO(114273) #19: mozilla::MozPromise<nsresult, mozilla::ipc::ResponseRejectReason, true>::ThenValueBase::ResolveOrRejectRunnable::Run() (/NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/mozilla/MozPromise.h:491)
00:55.33 GECKO(114273) #20: mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) [clone .cold] (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/threads/TaskController.cpp:880)
00:55.33 GECKO(114273) #21: mozilla::TaskController::ExecuteNextTaskOnlyMainThreadI

         [omission]

I am attaching the log itself.
It has some dumps from runtests.py regarding some environment setup and timeout values for debugging strange timeout issues which are observed locally.

I modified the code to dump the values of |this| pointer when PresShell::PresShell is allocated and
PresShell::Init(), and PresShell::Initialize() are called.
I print the stacktrace from PresShell::PresShell() after 100th call since the assertion is triggered after 107 or 108th calls to it in order to find out which routine allocates PresShell that later triggers assert.

As of now, C-C TB debug version shows 224 assertions during local mochitest.
224 is a tad too many. :-(

The number assertions dwindled to 184 during C-C mochitest as of yesterday. I don't know why exactly. It could be some tests that did not finish due to timeouts.

The line numbers are slightly off from pristine C-C TB due to local debug printf statements.

94:  Main Thread] ###!!! ASSERTION: should have done initial reflow by now: 'mDidInitialize', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/PresShell.cpp:3658
94:  Main Thread] ###!!! ASSERTION: should have done initial reflow by now: 'mDidInitialize', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/layout/base/PresShell.cpp:3587

The number of assertions triggered from the tests are as follows in the descending order of frequencies.
All seem to be triggered by a couple of scroll operations before mDidInitialize is set to true.
Frequency of assertions and the test name.

 34: comm/mail/components/addrbook/test/browser/browser_directory_tree.js
 32: comm/mail/components/addrbook/test/browser/browser_edit_card.js
 30: comm/mail/components/addrbook/test/browser/browser_contact_tree.js
 28: comm/mail/components/addrbook/test/browser/browser_cardDAV_init.js
 14: comm/mail/components/addrbook/test/browser/browser_open_actions.js
 12: comm/mail/components/addrbook/test/browser/browser_display_card.js
  6: comm/mail/components/addrbook/test/browser/browser_edit_async.js
  6: comm/mail/components/addrbook/test/browser/browser_drag_drop.js
  4: comm/mail/components/addrbook/test/browser/browser_display_multiple.js
  2: comm/mail/test/browser/message-window/browser_vcardActions.js
  2: comm/mail/test/browser/message-header/browser_messageHeader.js
  2: comm/mail/components/extensions/test/browser/browser_ext_addressBooksUI.js
  2: comm/mail/components/addrbook/test/browser/browser_search.js
  2: comm/mail/components/addrbook/test/browser/browser_mailing_lists.js
  2: comm/mail/components/addrbook/test/browser/browser_ldap_search.js
  2: comm/mail/components/addrbook/test/browser/browser_edit_photo.js
  2: comm/mail/components/addrbook/test/browser/browser_contact_sidebar.js
  2: comm/mail/components/addrbook/test/browser/browser_cardDAV_sync.js
  2: comm/mail/components/addrbook/test/browser/browser_cardDAV_properties.js
  2: comm/calendar/test/browser/browser_todayPane_visibility.js

I was so much concerned with " 'mDidInitialize'" variable name in the assertion, that I did not realize there is a bugzilla related to this error.
Bug 566159

In it, there are some analysis about the assertion.

In particular, https://bugzilla.mozilla.org/show_bug.cgi?id=566159#c3 and bug 566159 comment 4 seems to suggest that we need to have a certain flag to take care of the case when we don't have a frame and NOT to scroll.

Yes, I have seen the assertions when TB tries to scroll.


[task 2021-04-28T22:32:22.883Z] 22:32:22     INFO - GECKO(2300) | [Child 9124, Main Thread] ###!!! ASSERTION: should have done initial reflow by now: 'mDidInitialize', file /builds/worker/checkouts/gecko/layout/base/PresShell.cpp:3552
[task 2021-04-28T22:32:22.884Z] 22:32:22     INFO - GECKO(2300) | #01: NS_DebugBreak(unsigned int, char const*, char const*, char const*, int) [xpcom/base/nsDebugImpl.cpp:431]
[task 2021-04-28T22:32:22.884Z] 22:32:22     INFO - GECKO(2300) | #02: mozilla::PresShell::DoScrollContentIntoView() [layout/base/PresShell.cpp:3554]
[task 2021-04-28T22:32:22.884Z] 22:32:22     INFO - GECKO(2300) | #03: mozilla::PresShell::ScrollContentIntoView(nsIContent*, mozilla::ScrollAxis, mozilla::ScrollAxis, mozilla::ScrollFlags) [layout/base/PresShell.cpp:3549]
[task 2021-04-28T22:32:22.885Z] 22:32:22     INFO - GECKO(2300) | #04: nsFocusManager::ScrollIntoView(mozilla::PresShell*, nsIContent*, unsigned int) [dom/base/nsFocusManager.cpp:2820]
[task 2021-04-28T22:32:22.885Z] 22:32:22     INFO - GECKO(2300) | #05: nsFocusManager::Focus(nsPIDOMWindowOuter*, mozilla::dom::Element*, unsigned int, bool, bool, bool, bool, unsigned long long, mozilla::Maybe<nsFocusManager::BlurredElementInfo> const&) [dom/base/nsFocusManager.cpp:2572]
[task 2021-04-28T22:32:22.885Z] 22:32:22     INFO - GECKO(2300) | #06: nsFocusManager::SetFocusInner(mozilla::dom::Element*, int, bool, bool, unsigned long long) [dom/base/nsFocusM

I think it could be tractable. Anyone?

See Also: → 566159

The point seems to be that, due to async nature, we may not have child frame ready for scroll when we hit the assertion (?).
https://bugzilla.mozilla.org/show_bug.cgi?id=566159#c7 states

The reason that this new instance shows up is that the Fission work on the reftest harness, in general, makes things more async. So in this docshell/base/crashtests/1257730-1.html we previously tore down the page and moved on to the next test before being able to hit these assertions.

The asserts are slightly different because the stacks in docshell/base/crashtests/436900-2.html come from being asked to scroll, for docshell/base/crashtests/1257730-1.html the stacks come from a focus call from an autofocus form element.

I plan to annotate the new asserts as expected and point to this bug.

The assertions I noticed is from Focus() call, indeed.

Since the situation is asyncrhronous, the following may not be the best, but we may want to check
|GetPrimaryFrame()| and it if is nullptr, then return without assertion?
https://searchfox.org/mozilla-central/source/dom/base/nsIContent.h#535

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: