Closed
Bug 1784591
Opened 2 years ago
Closed 2 years 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)
Core
Widget: Win32
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
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•2 years ago
|
||
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
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 4•2 years ago
|
||
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)
|
|
||
Comment 5•2 years ago
|
||
These marionette jobs are also affected, might be the same root cause, treeherder link.
|
|
||
Comment 6•2 years ago
•
|
||
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
|
||
Comment 7•2 years ago
|
||
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.:
| Comment hidden (Intermittent Failures Robot) |
|
Assignee | |
Updated•2 years ago
|
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 10•2 years ago
|
||
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.
|
||
Comment 11•2 years ago
|
||
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
|
|
Assignee | |
Comment 12•2 years ago
|
||
Maybe Startup and Profile system is better here.
Component: Layout → Startup and Profile System
Product: Core → Toolkit
|
||
Comment 13•2 years ago
|
||
Sounds more likely to be a widget issue with focus.
Component: Startup and Profile System → Widget: Win32
Flags: needinfo?(dtownsend)
Product: Toolkit → Core
|
|
Assignee | |
Comment 14•2 years ago
|
||
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.
status-firefox104:
--- → unaffected
status-firefox105:
--- → affected
tracking-firefox105:
--- → ?
Flags: needinfo?(gijskruitbosch+bugs) → needinfo?(spohl.mozilla.bugs)
Keywords: regression,
regressionwindow-wanted
|
||
Comment 15•2 years ago
|
||
(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)
|
||
Comment 16•2 years ago
|
||
This sounds worse than an S4 to me. Back to the triage queue.
Severity: S4 → --
status-firefox103:
--- → unaffected
status-firefox-esr102:
--- → unaffected
status-firefox-esr91:
--- → unaffected
Priority: P5 → --
|
||
Comment 17•2 years ago
|
||
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)
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 19•2 years ago
|
||
(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_VALUEfrom 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:
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).
|
|
Assignee | |
Comment 20•2 years ago
|
||
(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
nsISupportsWeakReferenceor 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)
|
|
Assignee | |
Updated•2 years ago
|
Flags: needinfo?(hskupin)
|
|
Assignee | |
Comment 21•2 years ago
|
||
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)
|
|
Assignee | |
Comment 22•2 years ago
•
|
||
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.
|
|
Assignee | |
Comment 23•2 years ago
•
|
||
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.
|
|
Assignee | |
Comment 24•2 years ago
|
||
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-finishednotification is sent out when I click the Firefox icon in the taskbar
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 26•2 years ago
|
||
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.
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 28•2 years ago
•
|
||
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)
|
|
Assignee | |
Comment 29•2 years ago
|
||
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?
|
|
Assignee | |
Updated•2 years ago
|
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
|
||
Updated•2 years ago
|
QA Whiteboard: [qa-regression-triage]
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 32•2 years ago
|
||
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_PAINTbut 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_NCACTIVATEmessages 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 sendingWM_NCACTIVATEwith activate=TRUE. MSDN says that the message is only to communicate whether the window chrome should be drawn as active or inactive. TheWM_ACTIVATEandWM_ACTIVATEAPPmessages are about actual activation, not cosmetics. They do not mention a reason whyWM_NCACTIVATEmight 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)
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 34•2 years ago
|
||
(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)
|
|
Assignee | |
Comment 35•2 years ago
|
||
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.
|
|
Assignee | |
Comment 36•2 years ago
|
||
(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.
|
|
Assignee | |
Comment 37•2 years ago
|
||
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.
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 39•2 years ago
|
||
I'm unsure what's going on here. The following overview is based on this specific try failure:
- We start
schedule per window idle tasksand running each of the individual tasks. - This works all fine until gGFXUtils.init() is done.
- 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?
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 41•2 years ago
•
|
||
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:
- I modified the Marionette code to calculate the time for receiving the
browser-idle-startup-tasks-finishednotification 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. - 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) - When Firefox was in a broken state I was waiting nearly a minute before minimizing it via the task bar icon
- Restoring the window finally caused the
browser-idle-startup-tasks-finishednotification to be sent. - Then I entered Toolbar customization to add the profiler button to the tool bar.
- 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)
|
||
Comment 42•2 years ago
|
||
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)
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 44•2 years ago
|
||
(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.
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 46•2 years ago
•
|
||
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:
|
|
Assignee | |
Comment 47•2 years ago
|
||
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 50•2 years ago
•
|
||
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)
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 53•2 years ago
|
||
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.
|
||
Updated•2 years ago
|
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 55•2 years ago
|
||
(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="*".
|
||
Comment 56•2 years ago
|
||
(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=truedidn'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?
|
|
||
Comment 57•2 years ago
|
||
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: 2 years ago
status-firefox106:
--- → fixed
tracking-firefox106:
--- → +
Regressed by: 965392
Resolution: --- → FIXED
Target Milestone: --- → 106 Branch
|
||
Updated•2 years ago
|
Assignee: nobody → hskupin
Points: --- → 3
Priority: -- → P1
Whiteboard: [stockwell disable-recommended] → [stockwell disable-recommended] [webdriver:m4]
|
|
Assignee | |
Updated•2 years ago
|
Whiteboard: [stockwell disable-recommended] [webdriver:m4] → [stockwell disable-recommended][webdriver:m4][webdriver:external]
|
|
Assignee | |
Updated•2 years ago
|
|
|
||
Comment 58•2 years ago
|
||
Setting the status for 105 to disabled since the code which caused this regression is only built on Nightly.
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
You need to log in
before you can comment on or make changes to this bug.
Description
•