Closed Bug 1143504 Opened 9 years ago Closed 9 years ago

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

Categories

(Core :: DOM: Core & HTML, defect)

Product:
Core
Component:
DOM: Core & HTML
Platform:
x86
macOS
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla39
Tracking Flags:
Tracking Status
firefox39 --- fixed

People

(Reporter: ehsan.akhgari, Assigned: ehsan.akhgari)

References

Details

Attachments

(1 file)

Disconnect the Cache object from its actor when it gets cycle collected
2.82 KB, patch
bkelly
: review+
Details | Diff | Splinter Review 
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)
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)
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.
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
See Also: → 1145321
Attachment #8580227 - Flags: review?(bkelly) → review+
https://hg.mozilla.org/mozilla-central/rev/1cf05e26b761
Status: NEW → RESOLVED
Closed: 9 years ago
status-firefox39: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla39
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: