Closed Bug 1562948 Opened 4 months ago Closed 4 months ago

Intermittent testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py TestNavigate.test_focus_after_navigation | application crashed [@ 0x0 | InSendMessageExHook(void *)]

Categories

(Toolkit :: Startup and Profile System, defect, P1, critical)

defect

Tracking

()

RESOLVED FIXED
mozilla69
Tracking Status
firefox-esr60 --- wontfix
firefox-esr68 --- wontfix
firefox68 --- wontfix
firefox69 --- fixed

People

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

Details

(Keywords: crash, intermittent-failure, regression)

Crash Data

Attachments

(1 file)

Filed by: dluca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=254404488&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/MBY_5ZklQuG72TWFoKkBWg/runs/0/artifacts/public/logs/live_backing.log


TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py TestNavigate.test_focus_after_navigation
14:10:04     INFO -  1562076604737	Marionette	DEBUG	Accepted connection 508 from 127.0.0.1:50928
14:10:04     INFO -  1562076604740	Marionette	DEBUG	508 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
14:10:04     INFO -  1562076604743	Marionette	TRACE	[15032385537] Frame script loaded
14:10:04     INFO -  1562076604744	Marionette	TRACE	[15032385537] Frame script registered
14:10:04     INFO -  1562076604746	Marionette	DEBUG	508 <- [1,1,null,{"sessionId":"f57a7407-1b37-4eff-986c-d8654cd898fc","capabilities":{"browserName":"firefox","browserVersion":"69.0a ... p\\tmpa4scp_.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
14:10:04     INFO -  1562076604750	Marionette	DEBUG	508 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
14:10:04     INFO -  1562076604750	Marionette	DEBUG	508 <- [1,2,null,{"value":null}]
14:10:04     INFO -  1562076604752	Marionette	DEBUG	508 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
14:10:04     INFO -  1562076604752	Marionette	DEBUG	508 <- [1,3,null,{"value":null}]
14:10:04     INFO -  1562076604753	Marionette	DEBUG	508 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
14:10:04     INFO -  1562076604754	Marionette	DEBUG	508 <- [1,4,null,{"value":null}]
14:10:04     INFO -  1562076604758	Marionette	DEBUG	508 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
14:10:04     INFO -  1562076604758	Marionette	DEBUG	508 <- [1,5,null,{"value":"3"}]
14:10:04     INFO -  1562076604760	Marionette	DEBUG	508 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
14:10:04     INFO -  1562076604761	Marionette	DEBUG	508 <- [1,6,null,["3"]]
14:10:04     INFO -  1562076604763	Marionette	DEBUG	508 -> [0,7,"WebDriver:GetWindowHandle",{}]
14:10:04     INFO -  1562076604764	Marionette	DEBUG	508 <- [1,7,null,{"value":"15032385537"}]
14:10:04     INFO -  1562076604766	Marionette	DEBUG	508 -> [0,8,"WebDriver:GetWindowHandles",{}]
14:10:04     INFO -  1562076604766	Marionette	DEBUG	508 <- [1,8,null,["15032385537"]]
14:10:04     INFO -  1562076604769	Marionette	DEBUG	508 -> [0,9,"WebDriver:GetWindowHandles",{}]
14:10:04     INFO -  1562076604770	Marionette	DEBUG	508 <- [1,9,null,["15032385537"]]
14:10:04     INFO -  1562076604772	Marionette	DEBUG	508 -> [0,10,"WebDriver:NewWindow",{"type":"tab","focus":false}]
14:10:04     INFO -  1562076604781	Marionette	TRACE	Received DOM event TabOpen for [object XULElement]
14:10:04     INFO -  1562076604854	Marionette	TRACE	[70866960385] Frame script loaded
14:10:04     INFO -  1562076604857	Marionette	TRACE	[70866960385] Frame script registered
14:10:04     INFO -  1562076604883	Marionette	DEBUG	508 <- [1,10,null,{"handle":"70866960385","type":"tab"}]
14:10:04     INFO -  1562076604888	Marionette	DEBUG	508 -> [0,11,"WebDriver:GetWindowHandles",{}]
14:10:04     INFO -  1562076604889	Marionette	DEBUG	508 <- [1,11,null,["15032385537","70866960385"]]
14:10:04     INFO -  1562076604892	Marionette	DEBUG	508 -> [0,12,"WebDriver:GetWindowHandles",{}]
14:10:04     INFO -  1562076604893	Marionette	DEBUG	508 <- [1,12,null,["15032385537","70866960385"]]
14:10:04     INFO -  1562076604896	Marionette	DEBUG	508 -> [0,13,"WebDriver:SwitchToWindow",{"handle":"70866960385","focus":true,"name":"70866960385"}]
14:10:04     INFO -  1562076604912	Marionette	TRACE	Received DOM event TabSelect for [object XULElement]
14:10:04     INFO -  1562076604932	Marionette	DEBUG	508 <- [1,13,null,{"value":null}]
14:10:04     INFO -  1562076604939	Marionette	DEBUG	508 -> [0,14,"WebDriver:GetTimeouts",{}]
14:10:04     INFO -  1562076604939	Marionette	DEBUG	508 <- [1,14,null,{"implicit":0,"pageLoad":300000,"script":30000}]
14:10:04     INFO -  1562076604951	Marionette	DEBUG	508 -> [0,15,"WebDriver:ExecuteScript",{"script":"return window.history.length;","newSandbox":true,"args":[],"filename":"C:\\tasks\\ ... te\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_navigation.py","sandbox":"default","line":74}]
14:10:04     INFO -  1562076604956	Marionette	DEBUG	508 <- [1,15,null,{"value":1}]
14:10:04     INFO -  1562076604959	Marionette	DEBUG	508 -> [0,16,"Marionette:GetContext",{}]
14:10:04     INFO -  1562076604959	Marionette	DEBUG	508 <- [1,16,null,{"value":"content"}]
14:10:04     INFO -  1562076604965	Marionette	DEBUG	508 -> [0,17,"WebDriver:DeleteSession",{}]
14:10:04     INFO -  1562076604967	Marionette	DEBUG	508 <- [1,17,null,{"value":null}]
14:10:04     INFO -  1562076604970	Marionette	DEBUG	Closed connection 508
14:10:05     INFO -  Application command: C:\tasks\task_1562074245\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\testdr~1\appdata\local\temp\tmpa4scp_.mozrunner
14:12:05     INFO -  mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/B9vyt-rUSNOv8scpEhRZ1Q/artifacts/public/build/target.crashreporter-symbols.zip
14:12:14     INFO -  mozcrash Copy/paste: C:\tasks\task_1562074245\build\win32-minidump_stackwalk.exe c:\users\testdr~1\appdata\local\temp\tmpa4scp_.mozrunner\minidumps\1d78464c-ef5b-4ba7-8b84-1f19abcf2d67.dmp c:\users\testdr~1\appdata\local\temp\tmpjtytf9
14:12:24     INFO -  mozcrash Saved minidump as C:\tasks\task_1562074245\build\blobber_upload_dir\1d78464c-ef5b-4ba7-8b84-1f19abcf2d67.dmp
14:12:24     INFO -  mozcrash Saved app info as C:\tasks\task_1562074245\build\blobber_upload_dir\1d78464c-ef5b-4ba7-8b84-1f19abcf2d67.extra
14:12:24    ERROR -  PROCESS-CRASH | testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py TestNavigate.test_focus_after_navigation | application crashed [@ 0x0]
14:12:24     INFO -  Crash dump filename: c:\users\testdr~1\appdata\local\temp\tmpa4scp_.mozrunner\minidumps\1d78464c-ef5b-4ba7-8b84-1f19abcf2d67.dmp
14:12:24     INFO -  Operating system: Windows NT
14:12:24     INFO -                    10.0.17134
14:12:24     INFO -  CPU: 0x000c
14:12:24     INFO -       8 CPUs
14:12:24     INFO -  GPU: UNKNOWN
14:12:24     INFO -  Crash reason:  EXCEPTION_ACCESS_VIOLATION_EXEC
14:12:24     INFO -  Crash address: 0x0
14:12:24     INFO -  Process uptime: 0 seconds
14:12:24     INFO -  Thread 27 (crashed)
14:12:24     INFO -   0  0x0
14:12:24     INFO -      Found by: given as instruction pointer in context
14:12:24     INFO -   1  xul.dll!InSendMessageExHook(void *) [Compatibility.cpp:a15e5a44b7ed0a285c92839055efd83671b49552 : 117 + 0x8]
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -   2  combase.dll!AslHashFree + 0xe219c
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -   3  combase.dll!AslHashFree + 0x700f4
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -   4  combase.dll!AslHashFree + 0xeab10
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -   5  rpcrt4.dll!TokenExtCreateEnvironment + 0x4b4
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -   6  rpcrt4.dll!AslHashFree + 0x779e8
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -   7  combase.dll!AslHashFree + 0xe60e4
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -   8  combase.dll!AslHashFree + 0x18c48
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -   9  fastprox.dll!CptpQuirkSendEtwEvent + 0x110
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -  10  xul.dll!static bool QueryOneWMIProperty(struct IWbemServices *, const wchar_t *, const wchar_t *, struct tagVARIANT *) [nsAppRunner.cpp:a15e5a44b7ed0a285c92839055efd83671b49552 : 3513 + 0x18]
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -  11  xul.dll!static void AnnotateWMIData_ThreadStart(void *) [nsAppRunner.cpp:a15e5a44b7ed0a285c92839055efd83671b49552 : 3610 + 0x290]
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -  12  nss3.dll!static void _PR_NativeRunThread(void *) [pruthr.c:a15e5a44b7ed0a285c92839055efd83671b49552 : 397 + 0x4]
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -  13  nss3.dll!unsigned int pr_root(void *) [w95thred.c:a15e5a44b7ed0a285c92839055efd83671b49552 : 137 + 0x4]
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -  14  ucrtbase.dll!SortGetSortKey + 0x7a4
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -  15  kernel32.dll!BaseThreadInitThunk + 0x30
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -  16  mozglue.dll!static void patched_BaseThreadInitThunk(int, void *, void *) [WindowsDllBlocklist.cpp:a15e5a44b7ed0a285c92839055efd83671b49552 : 617 + 0x8]
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -  17  ntdll.dll!AslHashFree + 0x5468
14:12:24     INFO -      Found by: previous frame's frame pointer
14:12:24     INFO -  Thread 0

Happens for the call into DWORD result = sInSendMessageExStub(lpReserved);.

Aaron, do you have an idea?

Crash Signature: [@ 0x0] → [@ 0x0 | InSendMessageExHook(void *)]
Component: Marionette → Disability Access APIs
Flags: needinfo?(aklotz)
Product: Testing → Core
Summary: Intermittent testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py TestNavigate.test_focus_after_navigation | application crashed [@ 0x0] → Intermittent testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py TestNavigate.test_focus_after_navigation | application crashed [@ 0x0 | InSendMessageExHook(void *)]
Version: Version 3 → unspecified

Yes, looks like the real problem here is that we should use a multithreaded apartment in AnnotateWMIData_ThreadStart.

Assignee: nobody → aklotz
Status: NEW → ASSIGNED
Component: Disability Access APIs → Startup and Profile System
Flags: needinfo?(aklotz)
Priority: -- → P1
Product: Core → Toolkit

Using a single-threaded apartment creates a race condition that triggers a
crash in a11y when it hooks InSendMessageEx. Since we're on a background thread,
we don't have a strongly compelling reason to use an STA when an MTA will work
just fine.

Pushed by aklotz@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/42a9ef2a777f
Use a multi-threaded apartment inside AnnotateWMIData_ThreadStart; r=mhowell
Status: ASSIGNED → RESOLVED
Closed: 4 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla69
You need to log in before you can comment on or make changes to this bug.