Closed Bug 1784591 Opened 2 months ago Closed 1 month ago

Perma Windows shippable <random test> | application crashed [None] | After application terminated with exit code 1 | After application timed out after 370 seconds with no output

Categories

(Core :: Widget: Win32, defect, P1)

defect
Points:
3

Tracking

()

RESOLVED FIXED
106 Branch
Tracking Status
firefox-esr91 --- unaffected
firefox-esr102 --- unaffected
firefox103 --- unaffected
firefox104 --- unaffected
firefox105 + disabled
firefox106 + fixed

People

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

References

(Regression)

Details

(4 keywords, Whiteboard: [stockwell disable-recommended][webdriver:m4][webdriver:external])

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=387212832&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/A-59-Ow-QI-y84SMS6fazw/runs/0/artifacts/public/logs/live_backing.log


[task 2022-08-12T23:35:36.114Z] 23:35:36     INFO - TEST-START | browser/base/content/test/permissions/browser_canvas_rfp_exclusion.js
[task 2022-08-12T23:35:36.261Z] 23:35:36     INFO - GECKO(4352) | 1660347336271	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
[task 2022-08-12T23:35:36.831Z] 23:35:36     INFO - GECKO(4352) | 1660347336843	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
[task 2022-08-12T23:41:46.949Z] 23:41:46     INFO - Buffered messages logged at 23:35:36
[task 2022-08-12T23:41:46.951Z] 23:41:46     INFO - Entering test bound bound populatePlacedData
[task 2022-08-12T23:41:46.952Z] 23:41:46     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use <!DOCTYPE html>." {file: "https://example.com/" line: 0}]
[task 2022-08-12T23:41:46.953Z] 23:41:46     INFO - TEST-PASS | browser/base/content/test/permissions/browser_canvas_rfp_exclusion.js | Reading the placed data twice didn't match - "data:image/png;base64,iVBORw0KGgoAAAANSUhEUgAAAEAAAABACAYAAACqaXHeAAAAgElEQVR4Xu3XAREAMAgDMfAvGoR8JqE3muvO3U34rQD8ACegA8IdOEqQAhSgAAUoEE4AgxjEIAYxGEbAGMIgBjGIQQxiMJwABjGIQQxiMIyANYhBDGIQgxjEYDgBDGIQgxjEYBgBaxCDGMQgBjGIwXACGMQgBjGIwTAC1iAG6ww+gEm/gfQLwwkAAAAASUVORK5CYII=" == "data:image/png;base64,iVBORw0KGgoAAAANSUhEUgAAAEAAAABACAYAAACqaXHeAAAAgElEQVR4Xu3XAREAMAgDMfAvGoR8JqE3muvO3U34rQD8ACegA8IdOEqQAhSgAAUoEE4AgxjEIAYxGEbAGMIgBjGIQQxiMJwABjGIQQxiMIyANYhBDGIQgxjEYDgBDGIQgxjEYBgBaxCDGMQgBjGIwXACGMQgBjGIwTAC1iAG6ww+gEm/gfQLwwkAAAAASUVORK5CYII=" - 
[task 2022-08-12T23:41:46.954Z] 23:41:46     INFO - Leaving test bound bound populatePlacedData
[task 2022-08-12T23:41:46.954Z] 23:41:46     INFO - Entering test bound bound testCanvasRfpExclusion
[task 2022-08-12T23:41:46.955Z] 23:41:46     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use <!DOCTYPE html>." {file: "https://example.com/" line: 0}]
[task 2022-08-12T23:41:46.955Z] 23:41:46     INFO - Buffered messages finished
[task 2022-08-12T23:41:46.956Z] 23:41:46    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/permissions/browser_canvas_rfp_exclusion.js | application timed out after 370 seconds with no output
[task 2022-08-12T23:41:46.956Z] 23:41:46    ERROR - Force-terminating active process(es).
[task 2022-08-12T23:41:46.957Z] 23:41:46     INFO - Determining child pids from psutil...
.................................................................................
[task 2022-08-12T23:41:47.534Z] 23:41:47     INFO - TEST-INFO | Main app process: exit 1
[task 2022-08-12T23:41:47.535Z] 23:41:47     INFO - Buffered messages finished
[task 2022-08-12T23:41:47.535Z] 23:41:47    ERROR - TEST-UNEXPECTED-FAIL | browser/base/content/test/permissions/browser_canvas_rfp_exclusion.js | application terminated with exit code 1
[task 2022-08-12T23:41:47.536Z] 23:41:47     INFO - runtests.py | Application ran for: 0:06:19.074993
[task 2022-08-12T23:41:47.536Z] 23:41:47     INFO - zombiecheck | Reading PID log: C:\Users\task_166034245693738\AppData\Local\Temp\tmpznijibdfpidlog
..................................................................................................
[task 2022-08-12T23:41:51.021Z] 23:41:51     INFO - PROCESS-CRASH | browser/base/content/test/permissions/browser_canvas_rfp_exclusion.js | application crashed [None]
[task 2022-08-12T23:41:51.021Z] 23:41:51     INFO - Crash dump filename: C:\Users\task_166034245693738\AppData\Local\Temp\tmpgkfdq91y.mozrunner\minidumps\eb1104b8-e9bd-43af-b85e-ff8e61febc11.dmp
[task 2022-08-12T23:41:51.021Z] 23:41:51     INFO - stderr from minidump-stackwalk:
[task 2022-08-12T23:41:51.021Z] 23:41:51     INFO - ERROR MissingHeader - Error reading dump: Missing minidump header (empty minidump?)
[task 2022-08-12T23:41:51.030Z] 23:41:51     INFO - mozcrash Copy/paste: Z:/task_166034245693738/fetches\minidump-stackwalk\minidump-stackwalk.exe --symbols-url=https://symbols.mozilla.org/ --human C:\Users\task_166034245693738\AppData\Local\Temp\tmpgkfdq91y.mozrunner\minidumps\ddd9137b-1b0f-440f-a65b-be45a69bf225.dmp C:\Users\task_166034245693738\AppData\Local\Temp\tmp77qvmrw_
[task 2022-08-12T23:41:53.886Z] 23:41:53     INFO - mozcrash Saved minidump as Z:\task_166034245693738\build\blobber_upload_dir\ddd9137b-1b0f-440f-a65b-be45a69bf225.dmp
[task 2022-08-12T23:41:54.331Z] 23:41:54     INFO - PROCESS-CRASH | browser/base/content/test/permissions/browser_canvas_rfp_exclusion.js | application crashed [None]
[task 2022-08-12T23:41:54.331Z] 23:41:54     INFO - Crash dump filename: C:\Users\task_166034245693738\AppData\Local\Temp\tmpgkfdq91y.mozrunner\minidumps\ddd9137b-1b0f-440f-a65b-be45a69bf225.dmp
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO - Operating system: Windows NT
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO -                   10.0.19041
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO - CPU: amd64
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO -      family 6 model 85 stepping 4
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO -      8 CPUs
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO - 
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO - No crash
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO - Process uptime: 379 seconds
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO - 
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO - Thread 0 MainThread
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO -  0  mozglue.dll!moz_xrealloc(void*, unsigned long long) [mozalloc.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 78 + 0x3e]
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO -      rax = 0x000002a2ceb030f0    rdx = 0x0000000000000040
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO -      rcx = 0x00007ff8a88c3ca0    rbx = 0x000002a2de98aa00
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO -      rsi = 0x0000000000000040    rdi = 0x0000000000000001
[task 2022-08-12T23:41:54.338Z] 23:41:54     INFO -      rbp = 0x000002a2e90db960    rsp = 0x000000deaeffad50
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -       r8 = 0x0000000000000001     r9 = 0x000000deaeffafa0
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -      r10 = 0x00000fff1511232a    r11 = 0x0000040000000000
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -      r12 = 0x0000000000000000    r13 = 0x000002a2e03231c0
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -      r14 = 0x0000000000000040    r15 = 0x000002a2e90db900
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -      rip = 0x00007ff8a88c462b
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -     Found by: given as instruction pointer in context
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -  1  xul.dll!nsIFrame::MarkAsAbsoluteContainingBlock() [nsIFrame.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 324 + 0xde]
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -      rbx = 0x000002a2de98aa00    rsi = 0x0000000000000001
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -      rdi = 0x0000000000000001    rbp = 0x000002a2e90db960
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -      rsp = 0x000000deaeffae70    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -      r13 = 0x000002a2e03231c0    r14 = 0x0000000000000040
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -      r15 = 0x000002a2e90db900    rip = 0x00007ff889946065
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -  2  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x242]
[task 2022-08-12T23:41:54.339Z] 23:41:54     INFO -      rbx = 0x000002a2e90814a0    rsi = 0x000002a2def442e8
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      rdi = 0x000002a2e90db900    rbp = 0x000002a2e90db900
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      rsp = 0x000000deaeffaee0    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      r13 = 0x000002a2e90db900    r14 = 0x000002a2e90db900
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      r15 = 0x000002a2e90db900    rip = 0x00007ff889b9e462
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -  3  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      rbx = 0x000002a2e9081410    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90db838
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      rsp = 0x000000deaeffb210    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      r13 = 0x000002a2e90db838    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -  4  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      rbx = 0x000002a2e9081260    rsi = 0x0000000000000080
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90db530
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      rsp = 0x000000deaeffb540    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      r13 = 0x000002a2e90db530    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -  5  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      rbx = 0x000002a2e9081140    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90db468
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      rsp = 0x000000deaeffb870    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      r13 = 0x000002a2e90db468    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.340Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -  6  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      rbx = 0x000002a2e907e5c0    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90db0e0
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      rsp = 0x000000deaeffbba0    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      r13 = 0x000002a2e90db0e0    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -  7  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      rbx = 0x000002a2e907ead0    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90db018
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      rsp = 0x000000deaeffbed0    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      r13 = 0x000002a2e90db018    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -  8  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      rbx = 0x000002a2e907e920    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90dae00
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      rsp = 0x000000deaeffc200    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      r13 = 0x000002a2e90dae00    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.341Z] 23:41:54     INFO -  9  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rbx = 0x000002a2e907e800    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90dad38
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rsp = 0x000000deaeffc530    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      r13 = 0x000002a2e90dad38    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO - 10  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rbx = 0x000002a2e907e890    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90dac70
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rsp = 0x000000deaeffc860    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      r13 = 0x000002a2e90dac70    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO - 11  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rbx = 0x000002a2e907ec80    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90daae0
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rsp = 0x000000deaeffcb90    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      r13 = 0x000002a2e90daae0    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO - 12  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rbx = 0x000002a2e907eda0    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90da950
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      rsp = 0x000000deaeffcec0    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      r13 = 0x000002a2e90da950    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.342Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO - 13  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rbx = 0x000002a2e9081020    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90d8928
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rsp = 0x000000deaeffd1f0    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      r13 = 0x000002a2e90d8928    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO - 14  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rbx = 0x000002a2e90810b0    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90d8860
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rsp = 0x000000deaeffd520    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      r13 = 0x000002a2e90d8860    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO - 15  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rbx = 0x000002a2e907e2f0    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e90d8798
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rsp = 0x000000deaeffd850    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      r13 = 0x000002a2e90d8798    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO - 16  xul.dll!nsCSSFrameConstructor::ProcessChildren(nsFrameConstructorState&, nsIContent*, mozilla::ComputedStyle*, nsContainerFrame*, const bool, nsFrameList&, const bool, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 9809 + 0x3b5]
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rbx = 0x000002a2e907e140    rsi = 0x0000000000000088
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rdi = 0x000000deaeffe1a0    rbp = 0x000002a2e3f56868
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      rsp = 0x000000deaeffdb80    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      r13 = 0x000002a2e3f56868    r14 = 0x000000deaeffe200
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -      r15 = 0x000002a2e3f56198    rip = 0x00007ff889b9d8a0
[task 2022-08-12T23:41:54.343Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO - 17  xul.dll!nsCSSFrameConstructor::ConstructBlock(nsFrameConstructorState&, nsIContent*, nsContainerFrame*, nsContainerFrame*, mozilla::ComputedStyle*, nsContainerFrame**, nsFrameList&, nsIFrame*) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 10698 + 0x32]
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rbx = 0x000000deaeffdf60    rsi = 0x000000deaeffe1a0
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rdi = 0x000002a2e3f56198    rbp = 0x000000deaeffe200
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rsp = 0x000000deaeffdeb0    r12 = 0x0000100000000000
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      r13 = 0x000000000000000a    r14 = 0x000000deaeffe1a0
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      r15 = 0x000002a2e6e05480    rip = 0x00007ff888f6a9d7
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO - 18  xul.dll!nsCSSFrameConstructor::ContentRangeInserted(nsIContent*, nsIContent*, nsCSSFrameConstructor::InsertionKind) [nsCSSFrameConstructor.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 7088 + 0xfc]
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rbx = 0x0000000000000000    rsi = 0x000000deaeffe198
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rdi = 0x000002a2e794b100    rbp = 0x000002a2e905dd68
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rsp = 0x000000deaeffe020    r12 = 0x000002a2e794b100
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      r13 = 0x0000000000000000    r14 = 0x000002a2e6e05480
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      r15 = 0x000002a2e0369798    rip = 0x00007ff8881d52a0
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO - 19  xul.dll!mozilla::PresShell::Initialize() [PresShell.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 1863 + 0xf]
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rbx = 0x000002a2e3f56020    rsi = 0x000002a2dffe6000
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rdi = 0x000002a2e725ba00    rbp = 0x000000008000ffff
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rsp = 0x000000deaeffe340    r12 = 0xfffe000000000000
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      r13 = 0xfffdffffffffffff    r14 = 0x000002a2dffe6058
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      r15 = 0x00007ff8a889e860    rip = 0x00007ff8881d2f80
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO - 20  xul.dll!mozilla::dom::PrototypeDocumentContentSink::DoneWalking() [PrototypeDocumentContentSink.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 669 + 0x54]
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rbx = 0x000000deaeffe4f0    rsi = 0x000002a2e26ce670
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rdi = 0x000002a2dffe6000    rbp = 0x0000000000a23370
[task 2022-08-12T23:41:54.344Z] 23:41:54     INFO -      rsp = 0x000000deaeffe3b0    r12 = 0xfffe000000000000
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -      r13 = 0xfffdffffffffffff    r14 = 0x00000000da11fd01
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -      r15 = 0x00007ff8a889e860    rip = 0x00007ff888d8d65f
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO - 21  xul.dll!mozilla::dom::DocumentL10n::InitialTranslationCompleted(bool) [DocumentL10n.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 325 + 0xc]
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -      rbx = 0x000000deaeffe4f0    rsi = 0x000002a2e7adfb30
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -      rdi = 0x000000deaeffe4d0    rbp = 0x0000000000a23370
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -      rsp = 0x000000deaeffe4a0    r12 = 0xfffe000000000000
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -      r13 = 0xfffdffffffffffff    r14 = 0x00000000da11fd01
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -      r15 = 0x00007ff8a889e860    rip = 0x00007ff888ec99db
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO - 22  xul.dll!L10nReadyHandler::ResolvedCallback(JSContext*, JS::Handle<JS::Value>, mozilla::ErrorResult&) [DocumentL10n.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 75 + 0xa]
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -      rbx = 0x000000deaeffe690    rsi = 0x000002a2de98a8e0
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -      rdi = 0x000002a2de98a8e0    rbp = 0x0000000000000010
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -      rsp = 0x000000deaeffe5e0    r12 = 0xfffe000000000000
[task 2022-08-12T23:41:54.345Z] 23:41:54     INFO -      r13 = 0xfffdffffffffffff    r14 = 0x0000000000000001
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      r15 = 0x000002a2da11fd00    rip = 0x00007ff888ecc722
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO - 23  xul.dll!mozilla::dom::(anonymous namespace)::PromiseNativeHandlerShim::ResolvedCallback(JSContext*, JS::Handle<JS::Value>, mozilla::ErrorResult&) [Promise.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 431 + 0xf]
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rbx = 0x000000deaeffe690    rsi = 0x000002a2de98aa40
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rbp = 0x0000000000000010    rsp = 0x000000deaeffe630
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      r12 = 0xfffe000000000000    r13 = 0xfffdffffffffffff
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      r14 = 0x0000000000000001    r15 = 0x000002a2da11fd00
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rip = 0x00007ff888e891f7
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO - 24  xul.dll!mozilla::dom::NativeHandlerCallback(JSContext*, unsigned int, JS::Value*) [Promise.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 363 + 0x24]
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rbx = 0x000000deaeffe690    rsi = 0x000002a2da11fd00
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rdi = 0x000000deaeffe940    rbp = 0x0000000000000010
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rsp = 0x000000deaeffe670    r12 = 0xfffe000000000000
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      r13 = 0xfffdffffffffffff    r14 = 0x0000000000000001
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      r15 = 0x000002a2da11fd00    rip = 0x00007ff888e89411
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO - 25  xul.dll!js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) [Interpreter.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 642 + 0x365]
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rbx = 0x000002a2daf8d000    rsi = 0xffff800000000000
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rdi = 0xfffb000000000000    rbp = 0xfffc800000000000
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rsp = 0x000000deaeffe6f0    r12 = 0xfffe000000000000
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      r13 = 0xfffdffffffffffff    r14 = 0x000000deaeffe908
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      r15 = 0x000002a2da11fd00    rip = 0x00007ff889862de6
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO - 26  xul.dll!PromiseReactionJob(JSContext*, unsigned int, JS::Value*) [Promise.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 2241 + 0x73]
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rbx = 0x000000deaeffe8d0    rsi = 0x000000deaeffe908
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rdi = 0x000000deaeffe940    rbp = 0xfffc800000000000
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      rsp = 0x000000deaeffe810    r12 = 0xfff9800000000000
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      r13 = 0xfffe000000000000    r14 = 0x000000deaeffe8b8
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -      r15 = 0x000002a2da11fd00    rip = 0x00007ff8893197c4
[task 2022-08-12T23:41:54.346Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO - 27  xul.dll!js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) [Interpreter.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 642 + 0x365]
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      rbx = 0x000002a2daf8d000    rsi = 0xffff800000000000
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      rdi = 0xfffb000000000000    rbp = 0xfffc800000000000
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      rsp = 0x000000deaeffe990    r12 = 0xfffe000000000000
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      r13 = 0xfffdffffffffffff    r14 = 0x000000deaeffeaf8
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      r15 = 0x000002a2da11fd00    rip = 0x00007ff889862de6
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO - 28  xul.dll!JS::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) [CallAndConstruct.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 117 + 0x1f]
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      rbx = 0xfffa800000000000    rsi = 0x000000deaeffeb40
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      rdi = 0xfff9800000000000    rbp = 0x0000000000000000
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      rsp = 0x000000deaeffeab0    r12 = 0x000000deaeffec20
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      r13 = 0x000002a2da11fd00    r14 = 0x0000000000000000
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      r15 = 0xfff9800000000000    rip = 0x00007ff8898faf9a
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO - 29  xul.dll!mozilla::PromiseJobRunnable::Run(mozilla::AutoSlowOperation&) [CycleCollectedJSContext.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 213 + 0x16f]
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      rbx = 0x000021089c93cff0    rsi = 0x0000000000000000
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      rdi = 0x000002a2df26a900    rbp = 0x0000000000000000
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      rsp = 0x000000deaeffebd0    r12 = 0x000002a2df24d300
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      r13 = 0x000002a2db4a4400    r14 = 0x000000deaeffeee8
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      r15 = 0x000002a2e725ba00    rip = 0x00007ff889a3198e
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO - 30  xul.dll!mozilla::CycleCollectedJSContext::PerformMicroTaskCheckPoint(bool) [CycleCollectedJSContext.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 676 + 0x25]
[task 2022-08-12T23:41:54.347Z] 23:41:54     INFO -      rbx = 0x000002a2db4a4400    rsi = 0x0000000000000000
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      rdi = 0x000002a2db4a4400    rbp = 0x0000000000000000
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      rsp = 0x000000deaeffeea0    r12 = 0x000002a2df24d3c8
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      r13 = 0x000002a2da3f2000    r14 = 0x7fffffffffffffff
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      r15 = 0x000000deaeffeee8    rip = 0x00007ff889857d2a
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO - 31  xul.dll!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 1242 + 0x199]
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      rbx = 0x000002a2ceb5d708    rsi = 0x000002a2ceb39b00
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      rdi = 0x0000000000000000    rbp = 0x00007ff88a179a90
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      rsp = 0x000000deaeffefa0    r12 = 0x000002a2da3f2000
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      r13 = 0x000000000000f205    r14 = 0x000002a2ceb5d6f0
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      r15 = 0x7fffffffffffffff    rip = 0x00007ff88978a497
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO - 32  xul.dll!mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [MessagePump.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 85 + 0x28]
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      rbx = 0x000002a2ceb5d6f0    rsi = 0x000002a2ceb11400
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      rdi = 0x000002a2ceb41190    rbp = 0x0000000000000000
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      rsp = 0x000000deaefff340    r12 = 0x000000deaefffa01
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      r13 = 0x000000deaefff370    r14 = 0x000002a2ceb11420
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      r15 = 0x00007ff889788de0    rip = 0x00007ff889a73614
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO - 33  xul.dll!MessageLoop::RunHandler() [message_loop.cc:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 374 + 0x15]
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      rbx = 0x00007ff8a892f778    rsi = 0x000002a2ceb41190
[task 2022-08-12T23:41:54.348Z] 23:41:54     INFO -      rdi = 0x000002a2ceb5d6f0    rbp = 0x000000deaefff400
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      rsp = 0x000000deaefff3e0    r12 = 0x000000deaefffa20
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      r13 = 0x000000deaefffb19    r14 = 0x0000000080004005
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      r15 = 0x000002a2da2d2a60    rip = 0x00007ff88897ae9f
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO - 34  xul.dll!MessageLoop::Run() [message_loop.cc:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 356 + 0x4]
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      rbx = 0x00007ff8a892f778    rsi = 0x000000deaefff458
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      rdi = 0x000002a2ceb5d6f0    rbp = 0x0000000000000001
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      rsp = 0x000000deaefff430    r12 = 0x000000deaefffa20
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      r13 = 0x000000deaefffb19    r14 = 0x0000000080004005
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      r15 = 0x000002a2da2d2a60    rip = 0x00007ff887fb0b2e
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO - 35  xul.dll!nsBaseAppShell::Run() [nsBaseAppShell.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 150 + 0xc]
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      rbx = 0x00007ff8a892f778    rsi = 0x000002a2ceb5bf60
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      rbp = 0x0000000000000001    rsp = 0x000000deaefff490
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      r12 = 0x000000deaefffa20    r13 = 0x000000deaefffb19
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      r14 = 0x0000000080004005    r15 = 0x000002a2da2d2a60
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      rip = 0x00007ff888117d28
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO - 36  xul.dll!nsAppShell::Run() [nsAppShell.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 614 + 0x7]
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      rbx = 0x00007ff8a892f778    rsi = 0x000002a2ceb5bf60
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      rdi = 0x00007ff88b71d540    rbp = 0x0000000000000001
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      rsp = 0x000000deaefff4d0    r12 = 0x000000deaefffa20
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      r13 = 0x000000deaefffb19    r14 = 0x0000000080004005
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -      r15 = 0x000002a2da2d2a60    rip = 0x00007ff888116c27
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.349Z] 23:41:54     INFO - 37  xul.dll!nsAppStartup::Run() [nsAppStartup.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 295 + 0x10]
[task 2022-08-12T23:41:54.350Z] 23:41:54     INFO -      rbx = 0x000000deaefff748    rsi = 0x000002a2da3e9970
[task 2022-08-12T23:41:54.350Z] 23:41:54     INFO -      rdi = 0x0000000000000000    rbp = 0x000002a2ceb11f40
[task 2022-08-12T23:41:54.350Z] 23:41:54     INFO -      rsp = 0x000000deaefff650    r12 = 0x000000deaefffa20
[task 2022-08-12T23:41:54.350Z] 23:41:54     INFO -      r13 = 0x000000deaefffb19    r14 = 0x0000000080004005
[task 2022-08-12T23:41:54.350Z] 23:41:54     INFO -      r15 = 0x000002a2da2d2a60    rip = 0x00007ff88c6cff21
[task 2022-08-12T23:41:54.350Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.350Z] 23:41:54     INFO - 38  xul.dll!XREMain::XRE_mainRun() [nsAppRunner.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 5718 + 0x14]
[task 2022-08-12T23:41:54.350Z] 23:41:54     INFO -      rbx = 0x000000deaefff748    rsi = 0x000000deaefff700
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO -      rdi = 0x0000000000000000    rbp = 0x000002a2ceb11f40
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO -      rsp = 0x000000deaefff6a0    r12 = 0x000000deaefffa20
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO -      r13 = 0x000000deaefffb19    r14 = 0x0000000080004005
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO -      r15 = 0x000002a2da2d2a60    rip = 0x00007ff88c73bf26
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO - 39  xul.dll!XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [nsAppRunner.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 5912 + 0x7]
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO -      rbx = 0x0000000000000000    rsi = 0x000000deaefffa20
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO -      rdi = 0x000002a2ceb035f0    rbp = 0x000000deaefff978
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO -      rsp = 0x000000deaefff940    r12 = 0x000002a2ceb0a2e0
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO -      r13 = 0x0000000000000005    r14 = 0x000000deaefffa20
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO -      r15 = 0x0000000000000005    rip = 0x00007ff88c73cd8d
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.351Z] 23:41:54     INFO - 40  xul.dll!XRE_main(int, char**, mozilla::BootstrapConfig const&) [nsAppRunner.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 5968 + 0xf]
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -      rbx = 0x0000000000000005    rsi = 0x000000deaefffc10
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -      rdi = 0x000002a2ceb0a4c0    rbp = 0x000002a2ceb1b460
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -      rsp = 0x000000deaefffa00    r12 = 0x000002a2ceb0a2e0
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -      r13 = 0x0000000000000005    r14 = 0x000000deaefffa20
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -      r15 = 0x0000000000000005    rip = 0x00007ff889fa9e53
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO - 41  firefox.exe!wmain(int, wchar_t**) [nsWindowsWMain.cpp:fbae7216fa061be5b7521010f78bb51dade2a5a9 : 167 + 0x1bb]
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -      rbx = 0x000002a2ce863970    rsi = 0x000002a2ceb0a4c8
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -      rdi = 0x000002a2ceb0a4c0    rbp = 0x000002a2ceb1b460
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -      rsp = 0x000000deaefffb50    r12 = 0x000002a2ceb0a2e0
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -      r13 = 0x0000000000000005    r14 = 0x00007ff8a88a74c0
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -      r15 = 0x0000000000000005    rip = 0x00007ff60387bd28
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO - 42  firefox.exe!__scrt_common_main_seh() [exe_common.inl : 288 + 0x21]
[task 2022-08-12T23:41:54.352Z] 23:41:54     INFO -      rbx = 0x00007ff8c1d807a8    rsi = 0x0000000000000000
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      rdi = 0x000002a2ce8651b0    rbp = 0x0000000000000000
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      rsp = 0x000000deaefffe90    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      r13 = 0x0000000000000000    r14 = 0x0000000000000000
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff603889dd8
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO - 43  kernel32.dll!BaseThreadInitThunk + 0x13
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      rbx = 0x0000000000000000    rsi = 0x0000000000000000
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      rdi = 0x0000000000000000    rbp = 0x0000000000000000
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      rsp = 0x000000deaefffed0    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      r13 = 0x0000000000000000    r14 = 0x0000000000000000
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff8c34f7034
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO - 44  ntdll.dll!RtlUserThreadStart + 0x20
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      rbx = 0x0000000000000000    rbp = 0x0000000000000000
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      rsp = 0x000000deaeffff00    r12 = 0x0000000000000000
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      r13 = 0x0000000000000000    r14 = 0x0000000000000000
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -      r15 = 0x0000000000000000    rip = 0x00007ff8c3f22651
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO -     Found by: call frame info
[task 2022-08-12T23:41:54.353Z] 23:41:54     INFO - Thread 1 BrokerEvent
Summary: Intermittent <random test> | application crashed [None] | After application terminated with exit code 1 | After application timed out after 370 seconds with no output → Perma <random test> | application crashed [None] | After application terminated with exit code 1 | After application timed out after 370 seconds with no output

Something in this merge made thing go haywire on windows shippable mochitests: https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=fbae7216fa061be5b7521010f78bb51dade2a5a9

They are green on autoland, they timeout on central. Treeherder view with last good, first bad is here. One thing I've noticed is that lots of them have the crash with this line ERROR MissingHeader - Error reading dump: Missing minidump header (empty minidump?)
https://treeherder.mozilla.org/logviewer?job_id=387212832&repo=mozilla-central&lineNumber=2499
Aryx, could you have a look when you get the chance?

Flags: needinfo?(aryx.bugmail)

These marionette jobs are also affected, might be the same root cause, treeherder link.

See Also: → 1784625

Because of the presence of this line in some logs: https://treeherder.mozilla.org/logviewer?job_id=387281402&repo=mozilla-central&lineNumber=2479 I suspect it's from Bug 1781046.
Unfortunately can't confirm that backout on try because it doesn't timeout there, it does only on central. Might be a combination of test groups involved in this.

Summary: Perma <random test> | application crashed [None] | After application terminated with exit code 1 | After application timed out after 370 seconds with no output → Perma <random test> | application crashed [None] | After application terminated with exit code 1 | After application timed out after 370 seconds with no output

The way this fail is acting is a bit strange. It is indeed very frequent but from some retriggers it seems to be perma failing on specific jobs on Windows 10 x64 2004 WebRender Shippable, e.g.:

Depends on: 1784625
See Also: 1784625

While all these Mochitests are currently failing with timeouts due to an issue with Marionette finding the initial application window the underlying problem is within Firefox. When the browser starts the window gets opened but it is not accessible. Any user interaction fails for me when I see it happening on a local Microsoft Surface laptop by using a shippable build from mozilla-central. Focusing another application and going back to Firefox fixes it most of the times.

As Cosmin already mentioned above it doesn't fail when a shippable build from autoland is used nor when it gets pushed to try. As such making changes by adding more debug information doesn't help.

Flipping the dependency to the Marionette bug because it's actually blocked on a fix in Firefox.

We might need someone who is familar with debugging Firefox on Windows and can use a shippable build to reproduce and investigate.

Dave or Gijs, could one of you please help or forward to someone who could help here? Thanks a lot.

Blocks: 1784625
Component: Site Permissions → General
No longer depends on: 1784625
Flags: needinfo?(gijskruitbosch+bugs)
Flags: needinfo?(dtownsend)

The Bugbug bot thinks this bug should belong to the 'Core::Layout' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Component: General → Layout
Product: Firefox → Core

Maybe Startup and Profile system is better here.

Component: Layout → Startup and Profile System
Product: Core → Toolkit

Sounds more likely to be a widget issue with focus.

Component: Startup and Profile System → Widget: Win32
Flags: needinfo?(dtownsend)
Product: Toolkit → Core

There is at least nothing around focus changes in the following mozilla-central merge:
https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=fbae7216fa061be5b7521010f78bb51dade2a5a9

Stephen, do you have an idea why the startup on Windows is failing that often?

[Tracking Requested - why for this release]: Firefox opens not interoperable on Windows and at least needs a refocus. Regressed for the 105 branch.

Flags: needinfo?(gijskruitbosch+bugs) → needinfo?(spohl.mozilla.bugs)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #14)

There is at least nothing around focus changes in the following mozilla-central merge:
https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=fbae7216fa061be5b7521010f78bb51dade2a5a9

I don't see anything obviously suspicious in these changes. Comment 6 seems to point the finger at bug 1781046. Emilio, do you have any thoughts?

Flags: needinfo?(spohl.mozilla.bugs) → needinfo?(emilio)

This sounds worse than an S4 to me. Back to the triage queue.

Severity: S4 → --
Priority: P5 → --

Not really, all that code should be effectively preffed-off. How does comment 6 tie the error log line (NS_ERROR_ILLEGAL_VALUE from this call) to bug 1781046?

Henrik, is there anything interesting about that? NS_ERROR_ILLEGAL_VALUE is also NS_ERROR_INVALID_ARG: https://searchfox.org/mozilla-central/source/__GENERATED__/xpcom/base/ErrorList.h#68-69, which can come from a number of places from removeObserver, but maybe here? https://searchfox.org/mozilla-central/rev/5c04fc7016eb7f52cf835d482f1125c8f139c959/xpcom/base/nsMaybeWeakPtr.h#101-104

Is there any chance that the marionette driver didn't start up correctly so that it isn't a proper nsISupportsWeakReference or so? I don't see how tho.

Also, do we know that the regression is in comment 15's pushlog? Or is it just a guess based on timing? Because it seems we should be able to bisect it somehow?

Bug 1781084 would be my guess, based on "does something that potentially moves focus around when window visibility changes". But probably not it, not sure, wouldn't put my hand on the fire for it.

Flags: needinfo?(emilio) → needinfo?(hskupin)

(In reply to Emilio Cobos Álvarez (:emilio) from comment #17)

Not really, all that code should be effectively preffed-off. How does comment 6 tie the error log line (NS_ERROR_ILLEGAL_VALUE from this call) to bug 1781046?

I don't know but that is really a red herring and I fixed that part (to not disturb our investigation) over on bug 1784957. Here a newer log that shows this issue still:

https://treeherder.mozilla.org/logviewer?job_id=387536401&repo=mozilla-central&lineNumber=30738-30772

Also, do we know that the regression is in comment 15's pushlog? Or is it just a guess based on timing? Because it seems we should be able to bisect it somehow?

I was able to reproduce the hangs and that regression range on an old MS Surface. For details see bug 1784625 comment 12.

Bug 1781084 would be my guess, based on "does something that potentially moves focus around when window visibility changes". But probably not it, not sure, wouldn't put my hand on the fire for it.

I could check with Marionette in about one hour if the new behavior can be pref'ed off easily (I haven't taken a closer look yet).

(In reply to Emilio Cobos Álvarez (:emilio) from comment #17)

Is there any chance that the marionette driver didn't start up correctly so that it isn't a proper nsISupportsWeakReference or so? I don't see how tho.

Note that this error is raised when the given observer that needs to be removed hasn't been added before. And this was the case in this situation where Marionette code to start a new session errors out before adding it due to waiting for the initial window.

Flags: needinfo?(hskupin)
Flags: needinfo?(hskupin)

Sorry, but so far I've seen this issue only once today when running Marionette tests. And that didn't help me to check Emilio's idea. As such I hope that someone else can pick it up who is more familiar with the Firefox code base and debugging.

Flags: needinfo?(hskupin)

I just hit the hang with Marionette again. As mentioned before clicking somewhere inside the new window (eg new tab button) doesn't cause any reaction by Firefox. (Wrong assumption: But when I pressed the Alt key to open the main menu the browser-idle-startup-tasks-finished notification gets send out and Marionette continues). Maybe this helps.

A good way to reproduce seems to be the following command, pointing to a binary from a shippable build of mozilla-central:

./mach marionette-test --binary=path/to/firefox -vv --gecko-log=- testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py --run-until-failure

It might run for a while but eventually should fail.

Some additional information in case of brokeness:

  • The focus indicator is shown in the location bar but doesn't blink
  • The browser-idle-startup-tasks-finished notification is sent out when I click the Firefox icon in the taskbar

We tried to back out Bug 1781084 to see if that will fix this bug but it looks like it didn't: 1st fail
another fail
another fail
We'll reland Bug 1781084 and the ones that caused conflicts, before the next nightly.

When this problem appears the following Window events are sent:


[Parent 11196: Main Thread]: I/WindowsEvent      2 - 0x0046 (0x00000000 0x4FCC5FDCE0) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent      3 - 0x0083 (0x00000001 0x4FCC5FDCB0) WM_NCCALCSIZE: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent      4 - 0x0047 (0x00000000 0x4FCC5FDCE0) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent      5 - 0x007F (0x00000002 0x00000000) WM_GETICON: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent      6 - 0x007F (0x00000000 0x00000000) WM_GETICON: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent      7 - 0x007F (0x00000001 0x00000000) WM_GETICON: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent      8 - 0x0046 (0x00000000 0x4FCC5FD990) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent      9 - 0x0047 (0x00000000 0x4FCC5FD990) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     10 - 0x0046 (0x00000000 0x4FCC5FDBB0) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     11 - 0x0083 (0x00000001 0x4FCC5FDB80) WM_NCCALCSIZE: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     12 - 0x0047 (0x00000000 0x4FCC5FDBB0) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     13 - 0x000C (0x00000000 0x15BFBEBED48) WM_SETTEXT: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     14 - 0x0046 (0x00000000 0x4FCC5FC9B0) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     15 - 0x0083 (0x00000001 0x4FCC5FC980) WM_NCCALCSIZE: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     16 - 0x0047 (0x00000000 0x4FCC5FC9B0) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     17 - 0x0024 (0x00000000 0x4FCC5FCD00) WM_GETMINMAXINFO: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     18 - 0x0046 (0x00000000 0x4FCC5FCD00) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     19 - 0x0083 (0x00000001 0x4FCC5FCCD0) WM_NCCALCSIZE: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     20 - 0x0046 (0x00000000 0x4FCC5FCD00) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     21 - 0x001C (0x00000001 0x00000000) WM_ACTIVATEAPP: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     22 - 0x0086 (0x00000000 0x00000000) WM_NCACTIVATE: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     23 - 0x0086 (0x00000000 0x00000000) WM_NCACTIVATE: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     24 - 0x0006 (0x00000001 0x00000000) WM_ACTIVATE: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     25 - 0x0281 (0x00000001 0x4000000F) WM_IME_SETCONTEXT: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     26 - 0x0282 (0x00000002 0x00000000) WM_IME_NOTIFY: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     27 - 0x003D (0xFFFFFFFF 0xFFFFFFFC) WM_GETOBJECT: 0x0000C0A6 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     28 - 0x003D (0xFFFFFFFF 0x00000000) WM_GETOBJECT: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     29 - 0x003D (0x00000000 0xFFFFFFFFFFFFFFF4) WM_GETOBJECT: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     30 - 0x007F (0x00000001 0x00000060) WM_GETICON: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     31 - 0x0007 (0x00000000 0x00000000) WM_SETFOCUS: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     32 - 0x0085 (0x00000001 0x00000000) WM_NCPAINT: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     33 - 0x0014 (0x560106C1 0x00000000) WM_ERASEBKGND: 0x00000001 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     34 - 0x007F (0x00000002 0x00000060) WM_GETICON: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     35 - 0x0046 (0x00000000 0x4FCC5FC300) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     36 - 0x0083 (0x00000001 0x4FCC5FC2D0) WM_NCCALCSIZE: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     37 - 0x0085 (0x00000001 0x00000000) WM_NCPAINT: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     38 - 0x0014 (0xFFFFFFFFF501070E 0x00000000) WM_ERASEBKGND: 0x00000001 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     39 - 0x0047 (0x00000000 0x4FCC5FC300) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     40 - 0x0047 (0x00000000 0x4FCC5FCD00) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     41 - 0x0127 (0x00030001 0x00000000) WM_CHANGEUISTATE: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     42 - 0x0128 (0x00030001 0x00000000) WM_UPDATEUISTATE: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     43 - 0x007F (0x00000000 0x00000060) WM_GETICON: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     44 - 0x000F (0x00000000 0x00000000) WM_PAINT: 0x00000001 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     45 - 0x8316 (0x0974C633 0x00000000) Unknown: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     46 - 0xC0D1 (0x00000000 0x00000000) Unknown: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     47 - 0x0024 (0x00000000 0x4FCC5FE9E0) WM_GETMINMAXINFO: 0x00000000 (false)

Then when I minimize the window the following events are sent:

[Parent 11196: Main Thread]: I/WindowsEvent     48 - 0x0086 (0x00000001 0x00000000) WM_NCACTIVATE: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     49 - 0x0046 (0x00000000 0x4FCC5FE9E0) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 11196: Main Thread]: I/WindowsEvent     50 - 0x0047 (0x00000000 0x4FCC5FE9E0) WM_WINDOWPOSCHANGED: 0x00000000 (true)
*** You are running in background task mode. ***
*** You are running in headless mode.
[Parent 11196: Main Thread]: I/WindowsEvent     51 - 0x031F (0x00000001 0x00000000) WM_DWMNCRENDERINGCHANGED: 0x00000000 (false)
console.error: "C:\\Users\\henrik\\AppData\\Local\\Temp\\tmpca4zw6su.mozrunner" "" 0 ".purge.bg_rm"
[Parent 11196: Main Thread]: I/WindowsEvent     52 - 0x0086 (0x00000000 0x00000000) WM_NCACTIVATE: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     53 - 0x0006 (0x00000000 0x00000000) WM_ACTIVATE: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     54 - 0x001C (0x00000000 0x00001BD4) WM_ACTIVATEAPP: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     55 - 0x001C (0x00000000 0x00001BD4) WM_ACTIVATEAPP: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     56 - 0x0008 (0x00000000 0x00000000) WM_KILLFOCUS: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     57 - 0x0281 (0x00000000 0xC000000F) WM_IME_SETCONTEXT: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     58 - 0x0282 (0x00000001 0x00000000) WM_IME_NOTIFY: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     59 - 0x000C (0x00000000 0x7FFDB6535E32) WM_SETTEXT: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     60 - 0x007F (0x00000001 0x00000060) WM_GETICON: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     61 - 0x007F (0x00000002 0x00000060) WM_GETICON: 0x00000000 (false)
[Parent 11196: Main Thread]: I/WindowsEvent     62 - 0x007F (0x00000000 0x00000060) WM_GETICON: 0x00000000 (false)
1660901387345   Marionette      TRACE   Received observer notification browser-idle-startup-tasks-finished

In the working case the following events are visible:

[Parent 7260: Main Thread]: I/WindowsEvent      2 - 0x0046 (0x00000000 0x62D07FDB90) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent      3 - 0x0083 (0x00000001 0x62D07FDB60) WM_NCCALCSIZE: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent      4 - 0x0047 (0x00000000 0x62D07FDB90) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent      5 - 0x007F (0x00000002 0x00000000) WM_GETICON: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent      6 - 0x007F (0x00000000 0x00000000) WM_GETICON: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent      7 - 0x007F (0x00000001 0x00000000) WM_GETICON: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent      8 - 0x0046 (0x00000000 0x62D07FD840) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent      9 - 0x0047 (0x00000000 0x62D07FD840) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     10 - 0x0046 (0x00000000 0x62D07FDA60) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     11 - 0x0083 (0x00000001 0x62D07FDA30) WM_NCCALCSIZE: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     12 - 0x0047 (0x00000000 0x62D07FDA60) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     13 - 0x000C (0x00000000 0x2226B0E7528) WM_SETTEXT: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     14 - 0x0046 (0x00000000 0x62D07FE1A0) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     15 - 0x0083 (0x00000001 0x62D07FE170) WM_NCCALCSIZE: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     16 - 0x0047 (0x00000000 0x62D07FE1A0) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     17 - 0x0024 (0x00000000 0x62D07FE4F0) WM_GETMINMAXINFO: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     18 - 0x0046 (0x00000000 0x62D07FE4F0) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     19 - 0x0083 (0x00000001 0x62D07FE4C0) WM_NCCALCSIZE: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     20 - 0x0046 (0x00000000 0x62D07FE4F0) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     21 - 0x001C (0x00000001 0x00002A34) WM_ACTIVATEAPP: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     22 - 0x0086 (0x00000001 0x00000000) WM_NCACTIVATE: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     23 - 0x0086 (0x00000001 0x00000000) WM_NCACTIVATE: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     24 - 0x0006 (0x00000001 0x00000000) WM_ACTIVATE: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     25 - 0x0281 (0x00000001 0x4000000F) WM_IME_SETCONTEXT: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     26 - 0x0282 (0x00000002 0x00000000) WM_IME_NOTIFY: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     27 - 0x003D (0xFFFFFFFF 0xFFFFFFFC) WM_GETOBJECT: 0x0000C0FB (true)
[Parent 7260: Main Thread]: I/WindowsEvent     28 - 0x003D (0xFFFFFFFF 0x00000000) WM_GETOBJECT: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     29 - 0x003D (0x00000000 0xFFFFFFFFFFFFFFF4) WM_GETOBJECT: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     30 - 0x007F (0x00000001 0x00000060) WM_GETICON: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     31 - 0x0007 (0x00000000 0x00000000) WM_SETFOCUS: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     32 - 0x0085 (0x00000001 0x00000000) WM_NCPAINT: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     33 - 0x0014 (0xFFFFFFFF960108E8 0x00000000) WM_ERASEBKGND: 0x00000001 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     34 - 0x007F (0x00000002 0x00000060) WM_GETICON: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     35 - 0x0046 (0x00000000 0x62D07FDAF0) WM_WINDOWPOSCHANGING: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     36 - 0x0083 (0x00000001 0x62D07FDAC0) WM_NCCALCSIZE: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     37 - 0x0085 (0x00000001 0x00000000) WM_NCPAINT: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     38 - 0x0014 (0xFFFFFFFF960108E8 0x00000000) WM_ERASEBKGND: 0x00000001 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     39 - 0x0047 (0x00000000 0x62D07FDAF0) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     40 - 0x0047 (0x00000000 0x62D07FE4F0) WM_WINDOWPOSCHANGED: 0x00000000 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     41 - 0x0127 (0x00030001 0x00000000) WM_CHANGEUISTATE: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     42 - 0x0128 (0x00030001 0x00000000) WM_UPDATEUISTATE: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     43 - 0x007F (0x00000000 0x00000060) WM_GETICON: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     44 - 0x000F (0x00000000 0x00000000) WM_PAINT: 0x00000001 (true)
[Parent 7260: Main Thread]: I/WindowsEvent     45 - 0x8316 (0x097D96BB 0x00000000) Unknown: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     46 - 0xC0D1 (0x00000000 0x00000000) Unknown: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     47 - 0x0024 (0x00000000 0x62D07FE890) WM_GETMINMAXINFO: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     48 - 0x007C (0xFFFFFFFFFFFFFFF0 0x62D07FDC50) WM_STYLECHANGING: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     49 - 0x007D (0xFFFFFFFFFFFFFFF0 0x62D07FDC50) WM_STYLECHANGED: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     50 - 0x007C (0xFFFFFFFFFFFFFFEC 0x62D07FDCA0) WM_STYLECHANGING: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     51 - 0x007D (0xFFFFFFFFFFFFFFEC 0x62D07FDCA0) WM_STYLECHANGED: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     52 - 0x007C (0xFFFFFFFFFFFFFFF0 0x62D07FDCA0) WM_STYLECHANGING: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     53 - 0x007D (0xFFFFFFFFFFFFFFF0 0x62D07FDCA0) WM_STYLECHANGED: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     54 - 0x007C (0xFFFFFFFFFFFFFFEC 0x62D07FDCA0) WM_STYLECHANGING: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     55 - 0x007D (0xFFFFFFFFFFFFFFEC 0x62D07FDCA0) WM_STYLECHANGED: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     56 - 0x007C (0xFFFFFFFFFFFFFFEC 0x62D07FDD10) WM_STYLECHANGING: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     57 - 0x007D (0xFFFFFFFFFFFFFFEC 0x62D07FDD10) WM_STYLECHANGED: 0x00000000 (false)
console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\\Users\\henrik\\AppData\\Local\\Temp\\tmpuk6t9x2q.mozrunner\\search.json.mozlz4", (void 0)))
[Parent 7260: Main Thread]: I/WindowsEvent     58 - 0x031F (0x00000001 0x00000000) WM_DWMNCRENDERINGCHANGED: 0x00000000 (false)
[Parent 7260: Main Thread]: I/WindowsEvent     59 - 0x000C (0x00000000 0x7FFDB6535E32) WM_SETTEXT: 0x00000000 (false)
*** You are running in background task mode. ***
*** You are running in headless mode.
console.error: "C:\\Users\\henrik\\AppData\\Local\\Temp\\tmpuk6t9x2q.mozrunner" "" 0 ".purge.bg_rm"
[Parent 7260: Main Thread]: I/WindowsEvent     60 - 0x8316 (0x097DA12B 0x00000000) Unknown: 0x00000000 (false)
1660901804267   Marionette      TRACE   Received observer notification browser-idle-startup-tasks-finished
Flags: needinfo?(aryx.bugmail) → needinfo?(davidp99)

See also bug 1461353 (Startup hang in nsIWidget::Create on Windows 10) which was filed a while ago based on the test failures as seen on bug 1414495. Maybe that's the same underlying issue here as well?

Summary: Perma <random test> | application crashed [None] | After application terminated with exit code 1 | After application timed out after 370 seconds with no output → Perma Windows shippable <random test> | application crashed [None] | After application terminated with exit code 1 | After application timed out after 370 seconds with no output
QA Whiteboard: [qa-regression-triage]

Thanks to @whimboo, I can see a few additional things in a dump of the main process during the failure:

  • We are not still looking at the pre-XUL skeleton.
  • The window has painted at least once. We knew this from it processing WM_PAINT but we can also tell in the widget.
  • Window chrome layout was not completed. It doesn't even know where the max/min/close window buttons or the window-drag region are.
  • The application is "hung", waiting for another message from Windows. I don't know why basic mouse interaction doesn't cause it to unblock or why e.g. minimizing from the taskbar does. I suspect it's not hung in that mouse interactions probably would register -- they just would have no effect since no layout means there is nothing to "hit".
  • The non-client region layout values, computed as part of the response to e.g. WM_NCCALCSIZE, are sensible. Our logging doesn't tell us what the parameters were but the widget has expected values for these properties so the regions it is giving are sane. I don't know of anything else in the widget that could harm layout.
  • The WM_NCACTIVATE messages with activate=FALSE do seem to be the outlier, compared to successful runs. The messages after minimizing in comment 28 strongly suggest that the test framework won't find the window without Windows first sending WM_NCACTIVATE with activate=TRUE. MSDN says that the message is only to communicate whether the window chrome should be drawn as active or inactive. The WM_ACTIVATE and WM_ACTIVATEAPP messages are about actual activation, not cosmetics. They do not mention a reason why WM_NCACTIVATE might disagree about activation with the other activate messages. It seems nonsensical but it is what we see happening in comment 28.
  • None of the patches in the affected range seem relevant. There shouldn't be any way for us to cause this sequence of activation messages. But bug 1784287 is somewhat related to layout. But that's probably not it.

@whimboo: What do you see as the Fx window when it fails? Does it have any contents at all? (If so, can you post a screen shot?)

Flags: needinfo?(davidp99) → needinfo?(hskupin)

(In reply to David Parks [:handyman] from comment #32)

@whimboo: What do you see as the Fx window when it fails? Does it have any contents at all? (If so, can you post a screen shot?)

When such a failure happens the window and all of its widgets especially for the main Firefox UI are visible. So nothing seems to be broken. But as I mentioned above clicking on those doesn't cause any reaction. One thing to highlight though again is that the cursor which is by default set to the location bar doesn't blink. It's static means it's visible or not - depending on the timing when the window was shown.

In regards of the tab's content Marionette by default opens Firefox always with an initial about:blank tab. But modifying that to the default behavior by using about:newtab doesn't make a difference. While the about:newtab page is displayed the window doesn't react.

One thing to note, especially when seeing the above focus issue, is that Marionette uses the focus manager in test mode so that we an also interact with focus while the window is in the background. As such I flipped the preference to turn it off but also in that normal mode the hang is still visible. So we can exclude this feature as well.

Flags: needinfo?(hskupin) → needinfo?(davidp99)

This Mochitest failure is very interesting because it's not for a shippable build but a CCOV build and as the Marionette log shows it has the same underlying issue.

I'll check locally if I'm able to reproduce with a CCOV build as well and if that's the case maybe I can get it also to fail for try builds which would be great.

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #35)

I'll check locally if I'm able to reproduce with a CCOV build as well and if that's the case maybe I can get it also to fail for try builds which would be great.

Sadly I'm not able to use my usual Marionette test file to check for the startup hangs. The reason is that these CCOV builds are causing constant shutdown hangs and invalidate the testing. I'll have a look by running Mochitests which only restart Firefox when a new test folder is started. Maybe this helps.

Good news! I was able to get this failure on try with a CCOV build and some additional added log lines. The failure can be seen here:
https://treeherder.mozilla.org/logviewer?job_id=388093277&repo=try&lineNumber=10626-10668

[task 2022-08-22T17:55:26.272Z] 17:55:26     INFO - GECKO(7060) | 1661190926275	Marionette	DEBUG	Waiting for initial application window
[task 2022-08-22T17:55:26.310Z] 17:55:26     INFO - GECKO(7060) | 1661190926312	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:26.317Z] 17:55:26     INFO - GECKO(7060) | 1661190926316	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:26.320Z] 17:55:26     INFO - GECKO(7060) | 1661190926319	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:26.323Z] 17:55:26     INFO - GECKO(7060) | 1661190926322	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:26.325Z] 17:55:26     INFO - GECKO(7060) | 1661190926324	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:26.492Z] 17:55:26     INFO - GECKO(7060) | 1661190926497	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:26.542Z] 17:55:26     INFO - GECKO(7060) | 1661190926555	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:26.789Z] 17:55:26     INFO - GECKO(7060) | 1661190926796	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:26.857Z] 17:55:26     INFO - GECKO(7060) | 1661190926864	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:26.867Z] 17:55:26     INFO - GECKO(7060) | 1661190926866	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:26.878Z] 17:55:26     INFO - GECKO(7060) | ** Started onLoad
[task 2022-08-22T17:55:26.907Z] 17:55:26     INFO - GECKO(7060) | 1661190926905	Marionette	TRACE	Received observer notification browser-window-before-show
[task 2022-08-22T17:55:26.918Z] 17:55:26     INFO - GECKO(7060) | 1661190926930	Marionette	TRACE	Received observer notification user-interaction-active
[task 2022-08-22T17:55:26.959Z] 17:55:26     INFO - GECKO(7060) | 1661190926972	Marionette	TRACE	Received observer notification xul-window-visible
[task 2022-08-22T17:55:26.973Z] 17:55:26     INFO - GECKO(7060) | 1661190926972	Marionette	TRACE	Received observer notification xul-window-visible
[task 2022-08-22T17:55:27.011Z] 17:55:27     INFO - GECKO(7060) | 1661190927024	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:27.043Z] 17:55:27     INFO - GECKO(7060) | 1661190927042	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:27.048Z] 17:55:27     INFO - GECKO(7060) | 1661190927047	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:27.613Z] 17:55:27     INFO - GECKO(7060) | ** started delayed startup
[task 2022-08-22T17:55:27.621Z] 17:55:27     INFO - GECKO(7060) | 1661190927620	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:27.675Z] 17:55:27     INFO - GECKO(7060) | ** Policies status active? false
[task 2022-08-22T17:55:27.686Z] 17:55:27     INFO - GECKO(7060) | ** before _schedulePerWindowIdleTasks
[task 2022-08-22T17:55:27.686Z] 17:55:27     INFO - GECKO(7060) | ** after _schedulePerWindowIdleTasks
[task 2022-08-22T17:55:27.687Z] 17:55:27     INFO - GECKO(7060) | ** after _resolveDelayedStartup
[task 2022-08-22T17:55:27.693Z] 17:55:27     INFO - GECKO(7060) | 1661190927688	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
[task 2022-08-22T17:55:27.760Z] 17:55:27     INFO - GECKO(7060) | 1661190927759	Marionette	TRACE	Received observer notification sessionstore-windows-restored
[task 2022-08-22T17:55:27.788Z] 17:55:27     INFO - GECKO(7060) | ** started schedule per window idle tasks
[task 2022-08-22T17:55:27.813Z] 17:55:27     INFO - GECKO(7060) | *** You are running in background task mode. ***
[task 2022-08-22T17:55:27.826Z] 17:55:27     INFO - GECKO(7060) | *** You are running in headless mode.
[task 2022-08-22T17:55:27.853Z] 17:55:27     INFO - GECKO(7060) | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\\Users\\task_166118647693727\\AppData\\Local\\Temp\\tmphobk8sn7.mozrunner\\search.json.mozlz4", (void 0)))
[task 2022-08-22T17:55:27.929Z] 17:55:27     INFO - GECKO(7060) | 1661190927937	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:27.971Z] 17:55:27     INFO - GECKO(7060) | console.error: "C:\\Users\\task_166118647693727\\AppData\\Local\\Temp\\tmphobk8sn7.mozrunner" "" 0 ".purge.bg_rm"
[task 2022-08-22T17:55:27.986Z] 17:55:27     INFO - GECKO(7060) | 1661190927985	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:28.013Z] 17:55:28     INFO - GECKO(7060) | 1661190928025	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:28.038Z] 17:55:28     INFO - GECKO(7060) | 1661190928042	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:29.162Z] 17:55:29     INFO - GECKO(7060) | 1661190929166	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T17:55:29.304Z] 17:55:29     INFO - GECKO(7060) | 1661190929307	Marionette	TRACE	Received observer notification window-global-created
[task 2022-08-22T18:01:26.223Z] 18:01:26     INFO - runtests.py | Waiting for browser...
[task 2022-08-22T18:01:26.228Z] 18:01:26     INFO - GECKO(7060) | 1661191286228	Marionette	DEBUG	Failed to remove observer "browser-delayed-startup-finished"
[task 2022-08-22T18:01:26.231Z] 18:01:26     INFO - GECKO(7060) | 1661191286233	Marionette	DEBUG	Closed connection 1
[task 2022-08-22T18:07:36.269Z] 18:07:36     INFO - Buffered messages finished
[task 2022-08-22T18:07:36.269Z] 18:07:36    ERROR - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output
[task 2022-08-22T18:07:36.271Z] 18:07:36    ERROR - Force-terminating active process(es).

As it can be seen we receive a sessionstore-windows-restored notification and then started the schedule per window idle tasks. Once all the tasks are done the browser-idle-startup-tasks-finished notification should be sent out but it's not done in this case.

I assume that Firefox gets stuck in one of these tasks and never reaches the end. Adding more log lines should hopefully give us the necessary details. I'll trigger another try build.

I'm unsure what's going on here. The following overview is based on this specific try failure:

  1. We start schedule per window idle tasks and running each of the individual tasks.
  2. This works all fine until gGFXUtils.init() is done.
  3. The next task would be the one that finally emits browser-idle-startup-tasks-finished.

Sadly this task isn't started at all and as such the notification never gets sent out. The extra logging that I put into place can be seen here. Given that it logs only from within the idleTaskRunner callback for requestIdleCallback I would assume that the task never gets scheduled?

I assume the definition for requestIdleCallback is the one from nsGlobalWindowInner.cpp?

Ok, so I finally was able to retrieve a Gecko profile from such a hang. It can be found here: https://share.firefox.dev/3Ajrisj

Some comments in regards in how it has been created:

  1. I modified the Marionette code to calculate the time for receiving the browser-idle-startup-tasks-finished notification within the new session command and if longer than 10s it would enter a not resolving promise. This gives me time to actually get the profile data.
  2. I've run: MOZ_PROFILER_STARTUP=1 ./mach marionette-test --binary=path/to/firefox -vv --gecko-log=- testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py --run-until-failure (this enables startup profiling for the Firefox CCOV build)
  3. When Firefox was in a broken state I was waiting nearly a minute before minimizing it via the task bar icon
  4. Restoring the window finally caused the browser-idle-startup-tasks-finished notification to be sent.
  5. Then I entered Toolbar customization to add the profiler button to the tool bar.
  6. And finally I stopped the profiler and uploaded the profile.

I hope that this finally contains helpful information why this hang is taking place randomly.

Flags: needinfo?(smaug)

So per profile, idle tasks in general are running just fine. There are GC slices and https://searchfox.org/mozilla-central/source/browser/components/BrowserGlue.jsm#2862-2865 etc.

What I've been trying to figure out is that can the Window itself be suspended for some reason.

If you can reproduce somewhat easily, I'd try if widget.windows.window_occlusion_tracking.enabled = false affects this in some way.

Flags: needinfo?(smaug)

(In reply to Olli Pettay [:smaug][bugs@pettay.fi] from comment #42)

If you can reproduce somewhat easily, I'd try if widget.windows.window_occlusion_tracking.enabled = false affects this in some way.

I had a look yesterday and at least for the ccov build it didn't make a difference. But after talking to smaug and handyman the behavior that I can reproduce for CCOV builds might be something else. As such I will have to do the same checks later today with shippable builds. Further I'm planning to do tests with more logging added to Marionette code for shippable builds by directly modifying the JSMs from within the omni.ja file. Lets if this might help to get more details in where exactly it hangs.

See Also: → 1786242

As requested by Olli here another profile from a shippable build that contains all the registered threads: https://share.firefox.dev/3Ctz1XA

I also pushed a customized version of Marionette with additional logging to try as shippable artifact build and it caused a failure for a Marionette job: https://treeherder.mozilla.org/logviewer?job_id=388567846&repo=try&lineNumber=78708

I'm now going to re-check the regression range from earlier on this bug to see if it can be reproduced on try:

https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=windows%2Cship%2Cmn&tochange=fbae7216fa061be5b7521010f78bb51dade2a5a9&fromchange=66e3220110ba0dd99ba7d45684ac4731886a59a9

The try pushes for shippable builds (before, after the given merge) are not helpful given that all the Mn jobs are passing.

I think the profiles, which show browser-idle-startup-tasks-finished as being sent are the same issue and show that Marionette is just not receiving the message. The evidence is the SaveScripts thread that is created by StartCacheWrite in the profiles (see markers) in response to notifyObservers being called for browser-idle-startup-tasks-finished.

We can see that browser-idle-startup-tasks-finished isn't being received by Marionette because it would immediately resolve the browserStartupFinished promise, which would immediately unblock the driver, which is immediately followed by a lazy load of WindowManager.jsm, for which markers can be seen in successful profile runs like this one (...that isn't for the same tests as the failing profiles because I couldn't get profiles with e.g. the process in comment 41 since when doesn't fail). It does not appear in the failing profile runs.

My latest theory is that the failure is much earlier, and can also be seen in the profiles. Namely, a search of Marionette in the marker table shows the marionette-listening observable sent long before any of the stuff we have considered so far. Immediately after that, we send the port asynchronously with IOUtils, and that could be stalled for any number of reasons. However, in good runs, in the marker table, we see the PoisonIOInterposer writing the MarionetteActivePort file, but we never see it in bad profiles.

Flags: needinfo?(davidp99)

FYI maybe bug 965392 (Use a timer instead of a condvar to run the BHMgr Monitor thread) could be the culprit here. Disabling the background hang monitor via toolkit.content-background-hang-monitor.disabled=true didn't produce this startup hang yet when running a shippable build from mozilla-central locally. CC'ing Florian.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #46)

As requested by Olli here another profile from a shippable build that contains all the registered threads: https://share.firefox.dev/3Ctz1XA

This profile is weird, it looks like it is because you set the list of features to "samplingallthreads" (first time I see it used!), which disabled all the other features. The usual way to have all registered threads in a profile is to set the thread filter to '*', eg. MOZ_PROFILER_STARTUP_FILTERS="*".

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #53)

FYI maybe bug 965392 (Use a timer instead of a condvar to run the BHMgr Monitor thread) could be the culprit here. Disabling the background hang monitor via toolkit.content-background-hang-monitor.disabled=true didn't produce this startup hang yet when running a shippable build from mozilla-central locally. CC'ing Florian.

Could we add this to the automated test default user profile on infra to see if it resolves this on infra, giving us time to investigate further without this being such a problem for sheriffs?

Backing out bug 965392 appears to have indeed resolved these timeouts. I've reopened that bug and we can move the investigation over there.

Status: NEW → RESOLVED
Closed: 1 month ago
Regressed by: 965392
Resolution: --- → FIXED
Target Milestone: --- → 106 Branch
Assignee: nobody → hskupin
Points: --- → 3
Priority: -- → P1
Whiteboard: [stockwell disable-recommended] → [stockwell disable-recommended] [webdriver:m4]
Whiteboard: [stockwell disable-recommended] [webdriver:m4] → [stockwell disable-recommended][webdriver:m4][webdriver:external]
No longer blocks: 1629824
No longer blocks: 1414495
See Also: → 1414495

Setting the status for 105 to disabled since the code which caused this regression is only built on Nightly.

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