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

NEW
Unassigned

Status

()

Core
XPCOM
P3
normal
2 years ago
a year ago

People

(Reporter: RyanVM, Unassigned)

Tracking

(Blocks: 1 bug, {assertion, crash, intermittent-failure})

Trunk
assertion, crash, intermittent-failure
Points:
---

Firefox Tracking Flags

(e10s+, firefox47 affected)

Details

(Reporter)

Description

2 years ago
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

Comment 1

2 years ago
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)
(Reporter)

Comment 2

2 years ago
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)

Updated

2 years ago
tracking-e10s: ? → +
Intermittent test crash
Priority: -- → P3

Comment 6

a year ago
1 failures in 1008 pushes (0.001 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-beta: 1

Platform breakdown:
* windows8-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1253950&startday=2017-07-24&endday=2017-07-30&tree=all
You need to log in before you can comment on or make changes to this bug.