Closed Bug 1253950 Opened 8 years ago Closed 2 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: 2 years ago
status-firefox47: affected → wontfix
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.