784404 - Intermittent assertion in dom/devicestorage/test/test_basic.html ("Assertion failure: i < Length() (invalid array index), at e:\builds\moz2_slave\m-in-w32-dbg\build\obj-firefox\dist\include\nsTArray.h:526")

Status: RESOLVED FIXED

(Core :: DOM: Device Interfaces, defect)

Description

[Ed Morley [:emorley]]

A few of the other instances of this assertion have been marked as s-s, so doing so for this just in case.

Rev3 WINNT 6.1 mozilla-inbound debug test mochitests-2/5 on 2012-08-21 05:53:12 PDT for push 94f6e5a00d8b

slave: talos-r3-w7-068

https://tbpl.mozilla.org/php/getParsedLog.php?id=14560638&tree=Mozilla-Inbound

{
1 INFO TEST-START | /tests/dom/devicestorage/test/test_basic.html
1889 INFO TEST-PASS | /tests/dom/devicestorage/ipc/test_ipc.html | Got second iframe load event.
++DOMWINDOW == 9 (0847EC48) [serial = 9] [outer = 08588378]
[Child 2600] WARNING: NS_ENSURE_TRUE(IsChromeProcess()) failed: file e:/builds/moz2_slave/m-in-w32-dbg/build/content/base/src/nsFrameMessageManager.cpp, line 601
++DOMWINDOW == 10 (085C04E0) [serial = 10] [outer = 08588378]
1890 INFO TEST-PASS | /tests/dom/devicestorage/ipc/test_ipc.html | /tests/dom/devicestorage/test/test_basic.html |  Should have getDeviceStorage
1891 INFO TEST-PASS | /tests/dom/devicestorage/ipc/test_ipc.html | /tests/dom/devicestorage/test/test_basic.html |  Should have gotten a storage
1892 INFO TEST-PASS | /tests/dom/devicestorage/ipc/test_ipc.html | /tests/dom/devicestorage/test/test_basic.html |  Should have a non-null request
1893 INFO TEST-PASS | /tests/dom/devicestorage/ipc/test_ipc.html | /tests/dom/devicestorage/test/test_basic.html |  File name should match
1894 INFO TEST-PASS | /tests/dom/devicestorage/ipc/test_ipc.html | /tests/dom/devicestorage/test/test_basic.html |  addSuccess was called
1895 INFO TEST-PASS | /tests/dom/devicestorage/ipc/test_ipc.html | /tests/dom/devicestorage/test/test_basic.html |  Should have getDeviceStorage
1896 INFO TEST-PASS | /tests/dom/devicestorage/ipc/test_ipc.html | /tests/dom/devicestorage/test/test_basic.html |  File name should match
1897 INFO TEST-PASS | /tests/dom/devicestorage/ipc/test_ipc.html | /tests/dom/devicestorage/test/test_basic.html |  wrong arraybuffer byteLength - 69 should equal 69
1898 INFO TEST-PASS | /tests/dom/devicestorage/ipc/test_ipc.html | /tests/dom/devicestorage/test/test_basic.html |  wrong values - My name is Doug Turner.  My IRC nick is DougT.  I like Maple cookies. should equal My name is Doug Turner.  My IRC nick is DougT.  I like Maple cookies.
Assertion failure: i < Length() (invalid array index), at e:\builds\moz2_slave\m-in-w32-dbg\build\obj-firefox\dist\include\nsTArray.h:526
devicestorage/hi
[Child 2600] WARNING: shutting down early because of crash!: file e:/builds/moz2_slave/m-in-w32-dbg/build/dom/ipc/ContentChild.cpp, line 701
[Child 2600] WARNING: content process _exit()ing: file e:/builds/moz2_slave/m-in-w32-dbg/build/dom/ipc/ContentChild.cpp, line 746
nsStringStats
 => mAllocCount:           8042
 => mReallocCount:          587
 => mFreeCount:            3728  --  LEAKED 4314 !!!
 => mShareCount:          16580
 => mAdoptCount:            933
 => mAdoptFreeCount:        931  --  LEAKED 2 !!!
TEST-UNEXPECTED-FAIL | /tests/dom/devicestorage/test/test_basic.html | Exited with code -2147483645 during test run
INFO | automation.py | Application ran for: 0:04:34.412000
INFO | automation.py | Reading PID log: c:\users\cltbld\appdata\local\temp\tmpuclywqpidlog
==> process 3472 launched child process 2600
INFO | automation.py | Checking for orphan process with PID: 2600
Downloading symbols from: http://ftp.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-win32-debug/1345545301/firefox-17.0a1.en-US.win32.crashreporter-symbols.zip
PROCESS-CRASH | /tests/dom/devicestorage/test/test_basic.html | application crashed (minidump found)
Crash dump filename: c:\users\cltbld\appdata\local\temp\tmpinfdxz\minidumps\504e12ce-a5a6-48c1-91e6-06f09751a7d2.dmp
Operating system: Windows NT
                  6.1.7600 
CPU: x86
     GenuineIntel family 6 model 23 stepping 10
     2 CPUs

Crash reason:  EXCEPTION_BREAKPOINT
Crash address: 0x6ba98aee

Thread 0 (crashed)
 0  xul.dll!nsTArray<nsRefPtr<mozilla::dom::devicestorage::DeviceStorageRequestParent::CancelableRunnable>,nsTArrayDefaultAllocator>::ElementAt(unsigned int) [nsTArray.h:94f6e5a00d8b : 526 + 0x21]
    eip = 0x6ba98aee   esp = 0x0024d50c   ebp = 0x0024d514   ebx = 0x00000001
    esi = 0x13127704   edi = 0x00000001   eax = 0x00000000   ecx = 0x631477d2
    edx = 0x72a5e4d8   efl = 0x00000206
    Found by: given as instruction pointer in context
 1  xul.dll!mozilla::dom::devicestorage::DeviceStorageRequestParent::ActorDestroy(mozilla::ipc::IProtocolManager<mozilla::ipc::RPCChannel::RPCListener>::ActorDestroyReason) [DeviceStorageRequestParent.cpp:94f6e5a00d8b : 132 + 0x7]
    eip = 0x6ba9918e   esp = 0x0024d51c   ebp = 0x0024d538
    Found by: call frame info
 2  xul.dll!mozilla::dom::devicestorage::PDeviceStorageRequestParent::DestroySubtree(mozilla::ipc::IProtocolManager<mozilla::ipc::RPCChannel::RPCListener>::ActorDestroyReason) [PDeviceStorageRequestParent.cpp:94f6e5a00d8b : 332 + 0x10]
    eip = 0x6c2c8128   esp = 0x0024d530   ebp = 0x0024d538
    Found by: stack scanning
 3  xul.dll!mozilla::dom::devicestorage::PDeviceStorageRequestParent::Send__delete__(mozilla::dom::devicestorage::PDeviceStorageRequestParent *,mozilla::dom::devicestorage::DeviceStorageResponseValue const &) [PDeviceStorageRequestParent.cpp:94f6e5a00d8b : 96 + 0xa]
    eip = 0x6c2c8dd6   esp = 0x0024d540   ebp = 0x0024d574
    Found by: call frame info
 4  xul.dll!mozilla::dom::devicestorage::DeviceStorageRequestParent::PostPathResultEvent::CancelableRun() [DeviceStorageRequestParent.cpp:94f6e5a00d8b : 434 + 0x1f]
    eip = 0x6ba98eee   esp = 0x0024d57c   ebp = 0x0024d5b4
    Found by: call frame info
 5  xul.dll!mozilla::dom::devicestorage::DeviceStorageRequestParent::CancelableRunnable::Run() [DeviceStorageRequestParent.h:94f6e5a00d8b : 51 + 0x6]
    eip = 0x6ba9a88d   esp = 0x0024d5bc   ebp = 0x0024d5c4
    Found by: call frame info
 6  xul.dll!nsThread::ProcessNextEvent(bool,bool *) [nsThread.cpp:94f6e5a00d8b : 624 + 0xd]
    eip = 0x6c491e70   esp = 0x0024d5cc   ebp = 0x0024d5f4
    Found by: call frame info
 7  xul.dll!NS_ProcessNextEvent_P(nsIThread *,bool) [nsThreadUtils.cpp:94f6e5a00d8b : 220 + 0xc]
    eip = 0x6c4434f7   esp = 0x0024d5fc   ebp = 0x0024d608
    Found by: call frame info
 8  xul.dll!mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate *) [MessagePump.cpp:94f6e5a00d8b : 116 + 0x9]
    eip = 0x6c2ba253   esp = 0x0024d610   ebp = 0x0024d634
}

Comment 1

[Doug Turner (:dougt)]

The CancelableRunnable objects access mRunnables from multiple threads.  One CancelableRunnable event on the non-mail thread enumerating, the other is on an IO thread calling RemoveElements(). Yeah.

Comment 2

[Doug Turner (:dougt)]

Attachment: patch v.1

Comment 3

[Doug Turner (:dougt)]

Attachment: patch v.1

Comment 4

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Can't we do the remove from the array when you run the main thread success/failed response? Then you wouldn't need the lock at all.

Comment 5

[Doug Turner (:dougt)]

Attachment: patch v.1 - without damn locks

Comment 6

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Comment on attachment 654452 [details] [diff] [review]
patch v.1 - without damn locks

Review of attachment 654452 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/devicestorage/DeviceStorageRequestParent.h
@@ +50,5 @@
>        if (!mCanceled) {
>          rv = CancelableRun();
> +
> +        nsCOMPtr<nsIRunnable> event = NS_NewRunnableMethod(this, &CancelableRunnable::RemoveRunnable);
> +        NS_DispatchToMainThread(event);

You need to always do this, right? Even if you've been canceled. (Cancel doesn't currently remove from the array).

Comment 7

[Doug Turner (:dougt)]

I don't see a reason to fire this event if we have already cancelled.  We can just leave those in mRunnables and have them cleaned up when the parent goes away.

Comment 8

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Comment on attachment 654452 [details] [diff] [review]
patch v.1 - without damn locks

Review of attachment 654452 [details] [diff] [review]:
-----------------------------------------------------------------

Actually, if mCanceled is true you can't use mParent anyway (You'd crash). Sorry about that.

Comment 9

[Doug Turner (:dougt)]

https://hg.mozilla.org/mozilla-central/rev/a5ffaa0753dd

Comment 10

[Doug Turner (:dougt)]

Comment on attachment 653971 [details] [diff] [review]
patch v.1

locks are better:


[Parent 24662] ###!!! ASSERTION: Wrong thread!: 'NS_IsMainThread()', file /builds/mozilla-central/dom/devicestorage/DeviceStorageRequestParent.h, line 193
mozilla::dom::devicestorage::DeviceStorageRequestParent::AddRunnable(mozilla::dom::devicestorage::DeviceStorageRequestParent::CancelableRunnable*) (/builds/mozilla-central/dom/devicestorage/DeviceStorageRequestParent.h:194)
CancelableRunnable (/builds/mozilla-central/dom/devicestorage/DeviceStorageRequestParent.h:43)
PostPathResultEvent (/builds/mozilla-central/dom/devicestorage/DeviceStorageRequestParent.cpp:418)
mozilla::dom::devicestorage::DeviceStorageRequestParent::WriteFileEvent::CancelableRun() (/builds/mozilla-central/dom/devicestorage/DeviceStorageRequestParent.cpp:253)
mozilla::dom::devicestorage::DeviceStorageRequestParent::CancelableRunnable::Run() (/builds/mozilla-central/dom/devicestorage/DeviceStorageRequestParent.h:51)
nsThreadPool::Run() (/builds/mozilla-central/xpcom/threads/nsThreadPool.cpp:188)
nsThread::ProcessNextEvent(bool, bool*) (/builds/mozilla-central/xpcom/threads/nsThread.cpp:624)
NS_ProcessNextEvent_P(nsIThread*, bool) (/builds/mozilla-central/objdir-ff-dbg/xpcom/build/nsThreadUtils.cpp:220)
nsThread::ThreadFunc(void*) (/builds/mozilla-central/xpcom/threads/nsThread.cpp:256)
_pt_root (/builds/mozilla-central/nsprpub/pr/src/pthreads/ptthread.c:159)
start_thread (/build/buildd/eglibc-2.15/nptl/pthread_create.c:308)
clone (/build/buildd/eglibc-2.15/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:114)

Lets back out that other patch and use this.

Comment 11

[Doug Turner (:dougt)]

Comment on attachment 653971 [details] [diff] [review]
patch v.1

as bent pointed out, the parent could die and mMutex wouldn't be valid.

Comment 12

[Doug Turner (:dougt)]

more clarification - i can use a lock without any issue because the parent is refcounted.  The problem bent pointed out was that there is a race on created response runnables.  


10:48 <bent> you're on the main thread
10:48 <bent> you dispatch a runnable to io thread
10:48 <bent> your runnable starts to run on the io thread
10:48 <bent> checks mCanceled
10:48 <bent> it's false
10:48 <bent> so it does the real Run
10:48 <bent> does something
10:49 <bent> then the child crashes
10:49 <bent> now it's time to dispatch the response runnable
10:49 <bent> you lock, see that the actor has died, and can't add the runnable to the array
10:49 <bent> so you don't dispatch

Comment 13

[Doug Turner (:dougt)]

Attachment: patch v.2

Comment 14

[Doug Turner (:dougt)]

Attachment: patch v.2

Comment 15

[Doug Turner (:dougt)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/f50483a61327
https://hg.mozilla.org/integration/mozilla-inbound/rev/14968df0feee

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/14968df0feee
https://hg.mozilla.org/mozilla-central/rev/f50483a61327

Comment 17

[Al Billings [:abillings - ex-MoCo]]

Was Firefox 16 affected by this?