Closed Bug 1253950 Opened 10 years ago Closed 4 years ago

Intermittent browser_alarms.js | application crashed [@ mozilla::LazyIdleThread::AfterProcessNextEvent(nsIThreadInternal *,bool)] (Assertion failure: NS_GetCurrentThread() == mOwningThread (Wrong thread!))

Categories

(Core :: XPCOM, defect, P3)

Product:
Core
Component:
XPCOM
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE
Tracking Flags:
Tracking Status
e10s + ---
firefox47 --- wontfix

People

(Reporter: RyanVM, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: assertion, crash, intermittent-failure)

https://treeherder.mozilla.org/logviewer.html#?job_id=7826624&repo=fx-team 12:37:53 INFO - Assertion failure: NS_GetCurrentThread() == mOwningThread (Wrong thread!), at c:/builds/moz2_slave/fx-team-w32-d-0000000000000000/build/src/xpcom/threads/LazyIdleThread.cpp:526 12:37:53 INFO - Assertion failure: mPendingEventCount (Mismatched calls to observer methods!), at c:/builds/moz2_slave/fx-team-w32-d-0000000000000000/build/src/xpcom/threads/LazyIdleThread.cpp:546 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #01: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #02: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #03: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #04: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #05: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #06: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #07: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #08: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #09: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #10: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #11: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #12: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #13: ??? (???:???) 12:37:53 INFO - ### ERROR: SymInitialize: The parameter is incorrect. 12:37:53 INFO - #14: ??? (???:???) 12:38:07 INFO - TEST-INFO | Main app process: exit 1 12:38:07 WARNING - TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite 12:38:08 INFO - 341 INFO checking window state 12:38:08 INFO - 342 INFO Console message: [JavaScript Error: "TelemetryStopwatch: requesting elapsed time for nonexisting stopwatch. Histogram: "FX_PAGE_LOAD_MS", key: "null"" {file: "resource://gre/modules/TelemetryStopwatch.jsm" line: 297}] 12:38:08 INFO - this.TelemetryStopwatchImpl.timeElapsed@resource://gre/modules/TelemetryStopwatch.jsm:297:7 12:38:08 INFO - this.TelemetryStopwatchImpl.finish@resource://gre/modules/TelemetryStopwatch.jsm:315:17 12:38:08 INFO - this.TelemetryStopwatch.finish@resource://gre/modules/TelemetryStopwatch.jsm:192:12 12:38:08 INFO - TabsProgressListener.onStateChange@chrome://browser/content/browser.js:4640:11 12:38:08 INFO - callListeners@chrome://browser/content/tabbrowser.xml:501:24 12:38:08 INFO - _callProgressListeners@chrome://browser/content/tabbrowser.xml:522:13 12:38:08 INFO - mTabProgressListener/<._callProgressListeners@chrome://browser/content/tabbrowser.xml:571:22 12:38:08 INFO - mTabProgressListener/<.onStateChange@chrome://browser/content/tabbrowser.xml:729:15 12:38:08 INFO - stop@chrome://global/content/bindings/browser.xml:100:13 12:38:08 INFO - stop@chrome://browser/content/tabbrowser.xml:3816:20 12:38:08 INFO - Tester_waitForWindowsState@chrome://mochikit/content/browser-test.js:307:7 12:38:08 INFO - Tester.prototype.nextTest<@chrome://mochikit/content/browser-test.js:595:5 12:38:08 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:40 12:38:08 INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:395:7 12:38:08 INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:13 12:38:08 INFO - TaskImpl@resource://gre/modules/Task.jsm:280:3 12:38:08 INFO - createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14 12:38:08 INFO - testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1061:11 12:38:08 INFO - testScope/test_executeSoon/<.run@chrome://mochikit/content/browser-test.js:992:9 12:38:08 WARNING - TEST-UNEXPECTED-FAIL | hal/tests/browser_alarms.js | application terminated with exit code 1 12:38:08 INFO - runtests.py | Application ran for: 0:00:30.509000 12:38:08 INFO - zombiecheck | Reading PID log: c:\users\cltbld\appdata\local\temp\tmpn5xcvnpidlog 12:38:08 INFO - mozcrash Copy/paste: C:\slave\test\build\win32-minidump_stackwalk.exe c:\users\cltbld\appdata\local\temp\tmpgsnatx.mozrunner\minidumps\abece56b-98f2-4be3-a724-24f84e580b15.dmp C:\slave\test\build\symbols 12:38:27 INFO - mozcrash Saved minidump as C:\slave\test\build\blobber_upload_dir\abece56b-98f2-4be3-a724-24f84e580b15.dmp 12:38:27 INFO - mozcrash Saved app info as C:\slave\test\build\blobber_upload_dir\abece56b-98f2-4be3-a724-24f84e580b15.extra 12:38:27 WARNING - PROCESS-CRASH | hal/tests/browser_alarms.js | application crashed [@ mozilla::LazyIdleThread::AfterProcessNextEvent(nsIThreadInternal *,bool)] 12:38:27 INFO - Crash dump filename: c:\users\cltbld\appdata\local\temp\tmpgsnatx.mozrunner\minidumps\abece56b-98f2-4be3-a724-24f84e580b15.dmp 12:38:27 INFO - Operating system: Windows NT 12:38:27 INFO - 6.1.7601 Service Pack 1 12:38:27 INFO - CPU: x86 12:38:27 INFO - GenuineIntel family 6 model 30 stepping 5 12:38:27 INFO - 8 CPUs 12:38:27 INFO - Crash reason: EXCEPTION_BREAKPOINT 12:38:27 INFO - Crash address: 0x633dd49f 12:38:27 INFO - Process uptime: 31 seconds 12:38:27 INFO - Thread 65 (crashed) 12:38:27 INFO - 0 xul.dll!mozilla::LazyIdleThread::AfterProcessNextEvent(nsIThreadInternal *,bool) [LazyIdleThread.cpp:b29add2c1291 : 546 + 0x29] 12:38:27 INFO - eip = 0x633dd49f esp = 0x1b45f548 ebp = 0x1b45f55c ebx = 0x1b18b160 12:38:27 INFO - esi = 0x00000222 edi = 0x00000000 eax = 0x6668a968 ecx = 0x68950ad9 12:38:27 INFO - edx = 0x0035436b efl = 0x00000206 12:38:27 INFO - Found by: given as instruction pointer in context 12:38:27 INFO - 1 xul.dll!nsThread::ProcessNextEvent(bool,bool *) [nsThread.cpp:b29add2c1291 : 1005 + 0x13] 12:38:27 INFO - eip = 0x633e389a esp = 0x1b45f564 ebp = 0x1b45f64c 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 2 xul.dll!NS_ProcessNextEvent(nsIThread *,bool) [nsThreadUtils.cpp:b29add2c1291 : 297 + 0xd] 12:38:27 INFO - eip = 0x63412460 esp = 0x1b45f654 ebp = 0x1b45f660 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 3 xul.dll!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate *) [MessagePump.cpp:b29add2c1291 : 326 + 0xa] 12:38:27 INFO - eip = 0x636e12cc esp = 0x1b45f668 ebp = 0x1b45f68c 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 4 xul.dll!MessageLoop::RunInternal() [message_loop.cc:b29add2c1291 : 234 + 0xf] 12:38:27 INFO - eip = 0x636afb8d esp = 0x1b45f694 ebp = 0x1b45f6ac 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 5 xul.dll!MessageLoop::RunHandler() [message_loop.cc:b29add2c1291 : 227 + 0x5] 12:38:27 INFO - eip = 0x636afb45 esp = 0x1b45f6b4 ebp = 0x1b45f6e0 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 6 xul.dll!MessageLoop::Run() [message_loop.cc:b29add2c1291 : 201 + 0x7] 12:38:27 INFO - eip = 0x636af88f esp = 0x1b45f6e8 ebp = 0x1b45f700 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 7 xul.dll!nsThread::ThreadFunc(void *) [nsThread.cpp:b29add2c1291 : 396 + 0xc] 12:38:27 INFO - eip = 0x633e8d04 esp = 0x1b45f708 ebp = 0x1b45f740 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 8 nss3.dll!_PR_NativeRunThread [pruthr.c:b29add2c1291 : 397 + 0x6] 12:38:27 INFO - eip = 0x63155933 esp = 0x1b45f748 ebp = 0x1b45f760 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 9 nss3.dll!pr_root [w95thred.c:b29add2c1291 : 95 + 0xa] 12:38:27 INFO - eip = 0x63149974 esp = 0x1b45f768 ebp = 0x1b45f76c 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 10 msvcr120.dll!_callthreadstartex [threadex.c : 376 + 0x6] 12:38:27 INFO - eip = 0x6895c01d esp = 0x1b45f774 ebp = 0x1b45f7a4 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 11 msvcr120.dll + 0x2c001 12:38:27 INFO - eip = 0x6895c001 esp = 0x1b45f7ac ebp = 0x1b45f7b0 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 12 kernel32.dll!BaseThreadInitThunk + 0x12 12:38:27 INFO - eip = 0x75923c45 esp = 0x1b45f7b8 ebp = 0x1b45f7bc 12:38:27 INFO - Found by: previous frame's frame pointer 12:38:27 INFO - 13 ntdll.dll!__RtlUserThreadStart + 0x27 12:38:27 INFO - eip = 0x76fb37f5 esp = 0x1b45f7c4 ebp = 0x1b45f7fc 12:38:27 INFO - Found by: call frame info 12:38:27 INFO - 14 ntdll.dll!_RtlUserThreadStart + 0x1b 12:38:27 INFO - eip = 0x76fb37c8 esp = 0x1b45f804 ebp = 0x1b45f814 12:38:27 INFO - Found by: call frame info
Not sure why this was filed in IPC. Nathan can you take a look? Ryan is this windows-only? If it happens on Linux this sounds like a perfect candidate for rr/chaosmode.
Component: IPC → XPCOM
Flags: needinfo?(ryanvm)
Flags: needinfo?(nfroyd)
Just the one failure so far :)
Flags: needinfo?(ryanvm)
Looks like we can get registered as a thread observer after an event gets dispatched (and therefore not increment mPendingEventCount in LazyIdleThread::PreDispatch), but then mPendingEventCount gets decremented by AfterProcessNextEvent? At least that seems to explain the second assertion; I'm not sure what's up with the first assertion. This code is jesup's idea; let's see if he has any ideas.
Flags: needinfo?(nfroyd) → needinfo?(rjesup)
(In reply to Nathan Froyd [:froydnj] from comment #3) > Looks like we can get registered as a thread observer after an event gets > dispatched (and therefore not increment mPendingEventCount in > LazyIdleThread::PreDispatch), but then mPendingEventCount gets decremented > by AfterProcessNextEvent? > > At least that seems to explain the second assertion; I'm not sure what's up > with the first assertion. > > This code is jesup's idea; let's see if he has any ideas. Actually, this is much older code - most of this code is from 2010; the first MOZ_ASSERT for OnDispatchedEvent was just a rework from NS_ASSERTION in 2013 by cpeterson. I was the one proposing LazySingletonThread based on this code.
Flags: needinfo?(rjesup)
Intermittent test crash
Priority: -- → P3
Status: NEW → RESOLVED
Closed: 4 years ago
status-firefox47: affected → wontfix
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.