Intermittent assertion failure in dom/cache tests: Received response without a matching promise!

RESOLVED FIXED in Firefox 39

Status

()

Core
DOM
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: Ehsan, Assigned: Ehsan)

Tracking

unspecified
mozilla39
x86
Mac OS X
Points:
---

Firefox Tracking Flags

(firefox39 fixed)

Details

Attachments

(1 attachment)

(Assignee)

Description

3 years ago
I got this when I was retriggering mochitest-1 runs on Linux:

<http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/eakhgari@mozilla.com-0792a360d9b3/try-linux-debug/try_ubuntu32_vm-debug_test-mochitest-1-bm02-tests1-linux32-build333.txt.gz>

21:38:37     INFO -  Assertion failure: false (MOZ_ASSERT_UNREACHABLE: Received response without a matching promise!), at /builds/slave/try-lx-d-000000000000000000000/build/src/dom/cache/Cache.cpp:580
21:38:59     INFO -  #01: mozilla::dom::cache::Cache::RemoveRequestPromise(unsigned int) [dom/cache/Cache.cpp:580]
21:38:59     INFO -  #02: mozilla::dom::cache::Cache::RecvMatchAllResponse(unsigned int, nsresult, nsTArray<mozilla::dom::cache::PCacheResponse> const&) [mfbt/AlreadyAddRefed.h:109]
21:38:59     INFO -  #03: mozilla::dom::cache::CacheChild::RecvMatchAllResponse(unsigned int const&, nsresult const&, nsTArray<mozilla::dom::cache::PCacheResponse>&&) [dom/cache/CacheChild.cpp:129]
21:38:59     INFO -  #04: mozilla::dom::cache::PCacheChild::OnMessageReceived(IPC::Message const&) [obj-firefox/ipc/ipdl/PCacheChild.cpp:410]
21:38:59     INFO -  #05: mozilla::ipc::PBackgroundChild::OnMessageReceived(IPC::Message const&) [obj-firefox/ipc/ipdl/PBackgroundChild.cpp:1001]
21:38:59     INFO -  #06: mozilla::ipc::MessageChannel::DispatchAsyncMessage(IPC::Message const&) [ipc/glue/MessageChannel.h:506]
21:38:59     INFO -  #07: mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message const&) [ipc/glue/MessageChannel.cpp:1143]
21:38:59     INFO -  #08: mozilla::ipc::MessageChannel::OnMaybeDequeueOne() [ipc/glue/MessageChannel.cpp:1127]
21:38:59     INFO -  #09: RunnableMethod<mozilla::ipc::MessageChannel, bool (mozilla::ipc::MessageChannel::*)(), Tuple0>::Run() [ipc/chromium/src/base/tuple.h:383]
21:38:59     INFO -  #10: mozilla::ipc::MessageChannel::DequeueTask::Run() [ipc/glue/MessageChannel.h:445]
21:38:59     INFO -  #11: MessageLoop::RunTask(Task*) [ipc/chromium/src/base/message_loop.cc:362]
21:38:59     INFO -  #12: MessageLoop::DeferOrRunPendingTask(MessageLoop::PendingTask const&) [ipc/chromium/src/base/message_loop.cc:372]
21:38:59     INFO -  #13: MessageLoop::DoWork() [ipc/chromium/src/base/message_loop.cc:456]
21:38:59     INFO -  #14: mozilla::ipc::DoWorkRunnable::Run() [ipc/glue/MessagePump.cpp:234]
21:38:59     INFO -  #15: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:855]
21:38:59     INFO -  #16: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/glue/nsThreadUtils.cpp:265]
21:38:59     INFO -  #17: mozilla::dom::workers::WorkerPrivate::DoRunLoop(JSContext*) [dom/workers/WorkerPrivate.cpp:4754]
21:38:59     INFO -  #18: WorkerThreadPrimaryRunnable::Run [dom/workers/RuntimeService.cpp:2695]
21:38:59     INFO -  #19: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:855]
21:38:59     INFO -  #20: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/glue/nsThreadUtils.cpp:265]
21:38:59     INFO -  #21: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:368]
21:38:59     INFO -  #22: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:233]
21:38:59     INFO -  #23: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:517]
21:38:59     INFO -  #24: nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:358]
21:38:59     INFO -  #25: _pt_root [nsprpub/pr/src/pthreads/ptthread.c:215]
21:38:59     INFO -  #26: libpthread.so.0 + 0x6d4c

This suggests that we have received a response for which we don't have a corresponding promise.

This seems like a pretty bad logic error.  Ben, any theories on what may be going on here?
Flags: needinfo?(bkelly)

Comment 1

3 years ago
The current code here uses pointers as integer IDs.  The pointers could get reused and cause bad things to happen.  (Although I don't see how that would cause this directly.)

I don't think its worth tracking this down right now.  The entire request list thing is going to go away with bug 1110485.  I was considering punting that to v2, but I'm just going to do it this week.
Depends on: 1110485
Flags: needinfo?(bkelly)
(Assignee)

Comment 2

3 years ago
I just hit this under the debugger while debugging something unrelated.

When I cast aRequestId to a Promise*, the object looks sane:

(lldb) p *((mozilla::dom::Promise*)$4)
(mozilla::dom::Promise) $5 = {
  nsWrapperCache = {
    mWrapper = {
      ptr = 0x000000012fe16d00
    }
    mFlags = 0
  }
  mozilla::SupportsWeakPtr<mozilla::dom::Promise> = {
    mSelfReferencingWeakPtr = {
      mRef = {
        mPtr = 0x0000000128dcc480
      }
    }
  }
  mRefCnt = (mRefCntAndFlags = 7)
  _mOwningThread = (mThread = void * = 0x000000011a4d4d00)
  mGlobal = (mRawPtr = nsIGlobalObject * = 0x0000000000000000)
  mResolveCallbacks = {}
  mRejectCallbacks = {}
  mResult = {
    ptr = {
      data = {
        asBits = 18444773748872577024
        debugView = (payload47 = 0, tag = -14)
        s = {
          payload = (i32 = 0, u32 = 0, why = JS_ELEMENTS_HOLE)
        }
        asDouble = NaN
        asPtr = 0xfff9000000000000
        asWord = 18444773748872577024
        asUIntPtr = 18444773748872577024
      }
    }
  }
  mAllocationStack = {
    ptr = 0x0000000000000000
  }
  mRejectionStack = {
    ptr = 0x0000000000000000
  }
  mFullfillmentStack = {
    ptr = 0x0000000000000000
  }
  mState = Pending
  mHadRejectCallback = true
  mResolvePending = false
  mFeature = {
    mRawPtr = 0x0000000000000000
  }
  mCreationTimestamp = (mValue = 453071845671991)
  mSettlementTimestamp = (mValue = 0)
}

mRequestPromises at this point is an empty array!

Here is my stack:

Assertion failure: false (MOZ_ASSERT_UNREACHABLE: Received response without a matching promise!), at /Users/ehsan/moz/src/dom/cache/Cache.cpp:593
#01: mozilla::dom::cache::Cache::RemoveRequestPromise(unsigned long)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x296381d]
#02: mozilla::dom::cache::Cache::RecvAddAllResponse(unsigned long, nsresult)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x2963af7]
#03: mozilla::dom::cache::CacheChild::RecvAddAllResponse(unsigned long const&, nsresult const&)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x2964ec8]
#04: mozilla::dom::cache::PCacheChild::OnMessageReceived(IPC::Message const&)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0xcaaf76]
#05: mozilla::ipc::PBackgroundChild::OnMessageReceived(IPC::Message const&)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x87f48c]
#06: mozilla::ipc::MessageChannel::DispatchAsyncMessage(IPC::Message const&)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x82755e]
#07: mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message const&)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x826829]
#08: mozilla::ipc::MessageChannel::OnMaybeDequeueOne()[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x822de4]
#09: void DispatchToMethod<mozilla::ipc::MessageChannel, bool (mozilla::ipc::MessageChannel::*)()>(mozilla::ipc::MessageChannel*, bool (mozilla::ipc::MessageChannel::*)(), Tuple0 const&)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x841dc3]
#10: RunnableMethod<mozilla::ipc::MessageChannel, bool (mozilla::ipc::MessageChannel::*)(), Tuple0>::Run()[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x841cb6]
#11: mozilla::ipc::MessageChannel::RefCountedTask::Run()[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x846438]
#12: mozilla::ipc::MessageChannel::DequeueTask::Run()[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x846404]
#13: MessageLoop::RunTask(Task*)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x7be620]
#14: MessageLoop::DeferOrRunPendingTask(MessageLoop::PendingTask const&)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x7beb8f]
#15: MessageLoop::DoWork()[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x7bedb4]
#16: mozilla::ipc::DoWorkRunnable::Run()[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x82a722]
#17: nsThread::ProcessNextEvent(bool, bool*)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x18ca6f]
#18: NS_ProcessNextEvent(nsIThread*, bool)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x1e9b57]
#19: mozilla::dom::workers::WorkerPrivate::DoRunLoop(JSContext*)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x345b79b]
#20: (anonymous namespace)::WorkerThreadPrimaryRunnable::Run()[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x342740a]
#21: nsThread::ProcessNextEvent(bool, bool*)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x18ca6f]
#22: NS_ProcessNextEvent(nsIThread*, bool)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x1e9b57]
#23: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x82ae53]
#24: MessageLoop::RunInternal()[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x7be505]
#25: MessageLoop::RunHandler()[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x7be415]
#26: MessageLoop::Run()[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x7be3bd]
#27: nsThread::ThreadFunc(void*)[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/XUL +0x18af1b]
#28: _pt_root[/Users/ehsan/moz/src/obj-ff-clang-plugin.noindex/dist/NightlyDebug.app/Contents/MacOS/libnss3.dylib +0x372847]
#29: _pthread_body[/usr/lib/system/libsystem_pthread.dylib +0x3268]
#30: _pthread_body[/usr/lib/system/libsystem_pthread.dylib +0x31e5]

More investigation coming, chatting with nsm on IRC.
(Assignee)

Comment 3

3 years ago
So, the mGlobal member of both the Cache object and the Promise object are null, which means that they have both been CCed, which explains why mRequestPromises is empty.

But there is nothing which causes the CacheChild::mListener pointer pointing to the Cache object to be nulled out when the Cache object gets CCed, which means CacheChild still thinks it's dealing with a valid Cache object, which explains everything.

We need to do what we do in ~Cache() in its Unlink method as well.  Patch coming up.
Assignee: nobody → ehsan
(Assignee)

Comment 4

3 years ago
Created attachment 8580227 [details] [diff] [review]
Disconnect the Cache object from its actor when it gets cycle collected
Attachment #8580227 - Flags: review?(bkelly)
(Assignee)

Updated

3 years ago
See Also: → bug 1145321

Updated

3 years ago
Attachment #8580227 - Flags: review?(bkelly) → review+
https://hg.mozilla.org/mozilla-central/rev/1cf05e26b761
Status: NEW → RESOLVED
Last Resolved: 3 years ago
status-firefox39: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla39
You need to log in before you can comment on or make changes to this bug.