910484 - BluetoothDBusService.cpp: Assertion: "reacquiring already acquired resource"

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Bluetooth, defect)

Description

[Gregor Wagner [:gwagner]]

I see this on trunk during startup on unagi with a debug build.

WARNING: NS_ENSURE_TRUE(mA2dpConnected) failed: file /Volumes/mac/moz/ws0/dom/bluetooth/BluetoothA2dpManager.cpp, line 169
[New Thread 682.712]
[Switching to Thread 682.712]

Breakpoint 1, NS_DebugBreak (aSeverity=1, aStr=0x42b9f884 "reacquiring already acquired resource", aExpr=<value optimized out>, aFile=<value optimized out>, aLine=138) at /Volumes/mac/moz/ws0/xpcom/base/nsDebugImpl.cpp:302
302	     sevString = "###!!! ASSERTION";
(gdb) bt
#0  NS_DebugBreak (aSeverity=1, aStr=0x42b9f884 "reacquiring already acquired resource", aExpr=<value optimized out>, aFile=<value optimized out>, aLine=138) at /Volumes/mac/moz/ws0/xpcom/base/nsDebugImpl.cpp:302
#1  0x41f86a82 in mozilla::BlockingResourceBase::Acquire (this=0x431e820c, aCallContext=...) at /Volumes/mac/moz/ws0/otorodebug/xpcom/build/BlockingResourceBase.cpp:137
#2  0x41f874d0 in mozilla::OffTheBooksMutex::Lock (this=0x431e820c) at /Volumes/mac/moz/ws0/otorodebug/xpcom/build/BlockingResourceBase.cpp:226
#3  0x41750752 in mozilla::Monitor::Lock (this=0x444a8bf0) at ../../dist/include/mozilla/Monitor.h:37
#4  MonitorAutoLock (this=0x444a8bf0) at ../../dist/include/mozilla/Monitor.h:92
#5  mozilla::dom::bluetooth::BluetoothDBusService::StopInternal (this=0x444a8bf0) at /Volumes/mac/moz/ws0/dom/bluetooth/linux/BluetoothDBusService.cpp:1726
#6  0x4175415e in mozilla::dom::bluetooth::BluetoothGonkService::StopInternal (this=0x444a8bf0) at /Volumes/mac/moz/ws0/dom/bluetooth/gonk/BluetoothGonkService.cpp:143
#7  0x41737446 in mozilla::dom::bluetooth::BluetoothService::ToggleBtTask::Run (this=0x469b6f90) at /Volumes/mac/moz/ws0/dom/bluetooth/BluetoothService.cpp:205
#8  0x41fc9fd4 in nsThread::ProcessNextEvent (this=0x46fb62e0, mayWait=<value optimized out>, result=0x475ffe8f) at /Volumes/mac/moz/ws0/xpcom/threads/nsThread.cpp:622
#9  0x41f8e4be in NS_ProcessNextEvent (thread=0x46fb62e0, mayWait=true) at /Volumes/mac/moz/ws0/otorodebug/xpcom/build/nsThreadUtils.cpp:238
#10 0x41fca660 in nsThread::ThreadFunc (arg=<value optimized out>) at /Volumes/mac/moz/ws0/xpcom/threads/nsThread.cpp:250
#11 0x40a32656 in _pt_root (arg=<value optimized out>) at /Volumes/mac/moz/ws0/nsprpub/pr/src/pthreads/ptthread.c:204
#12 0x40140e18 in __thread_entry (func=0x40a325b5 <_pt_root>, arg=0x46cf4a80, tls=<value optimized out>) at bionic/libc/bionic/pthread.c:217
#13 0x4014096c in pthread_create (thread_out=<value optimized out>, attr=0xbea4af7c, start_routine=0x40a325b5 <_pt_root>, arg=0x46cf4a80) at bionic/libc/bionic/pthread.c:357
#14 0x00000000 in ?? ()

Comment 1

[Gina Yeh [:gyeh] [:ginayeh]]

Thanks for reporting. I'll take a look at this.

Comment 2

[Eric Chou [:ericchou] [:echou]]

ok, I can reproduce by following STRs below:

= STR 1 =
(1) Flash debug build to my FxOS device
(2) Make sure Bluetooth is off
(3) Reboot

= STR 2 =
(1) Flash debug build to my FxOS device
(2) Make sure Bluetooth is on
(3) Reboot
(4) Turn off Bluetooth

The assertion would be hit in both cases.

= Description =
I declared a static Monitor variable: sStopBluetoothMonitor in BluetoothDBusService.cpp, and used a MonitorAutoLock to hold it in StopInternal(), and I got the same backtrace as Greg's after calling the ctor of MonitorAutoLock.

From frame 2 of the backtrace, we can tell that the root cause is

  sStopBluetoothMonitor.mMutex.mDDEntry->mAcquisitionContext != CallStack::kNone

This is unexpected because mAcquisitionContext should be initialized to CallStack::kNone in ctor of DeadlockDetectorEntry, the class of mDDEntry, and I can confirm that the value of mAcquisitionContext hasn't been changed. So I retrieved the value and it looked like:

  (gdb) p sStopBluetoothMonitor.mMutex.mDDEntry->mAcquisitionContext 
  $2 = {mCallStack = 0x0, static kNone = {mCallStack = 0xffffffff, 
        static kNone = <same as static member of an already seen type>}}

As you can see, mCallStack was 0xffffffff in CallStack::kNone, but it was 0x0 in mAcquisitionContext. They were different so that the assertion was shown.

Not 100% sure how this happened. My guess is because sStopBluetoothMonitor was created earlier than CallStack::kNone, so the ctor of CallStack::kNone had not executed yet, and the value of CallStack::kNone was still cleared to 0.

This is a debug-build-only issue and it only happens on the first time Bluetooth is turned off. After that, mAcquisitionContext will be set to CallStack::kNon again, and the value will be correct.

Comment 3

[Eric Chou [:ericchou] [:echou]]

Steal this bug from Gina!

Comment 4

[Eric Chou [:ericchou] [:echou]]

Attachment: patch 1: v1: use a pointer to hold a global static variable to avoid assertion

Hi Blake,

Please review my patch. In order to avoid the assertion, which occurs because we can't control the order of contruction of global static variables, I changed to use a pointer instead of an instance, so I can really allocate the memory block at the other place (in ctor of BluetoothDBusService).

It's a small patch. Hope it won't take too much of your time.

Thank you.

- Eric

Comment 5

[Blake Kaplan (:mrbkap) (inactive)]

Comment on attachment 798801 [details] [diff] [review]
patch 1: v1: use a pointer to hold a global static variable to avoid assertion

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

::: dom/bluetooth/linux/BluetoothDBusService.cpp
@@ +177,5 @@
>  static nsTArray<uint32_t> sAuthorizedServiceClass;
>  static nsString sAdapterPath;
>  static Atomic<int32_t> sIsPairing(0);
>  static int sConnectedDeviceCount = 0;
> +static Monitor* sStopBluetoothMonitor = nullptr;

I'd probably make this a static nsAutoPtr.

@@ +189,5 @@
> +}
> +
> +BluetoothDBusService::~BluetoothDBusService()
> +{
> +  delete sStopBluetoothMonitor;

And simply set sStopBluetoothMonitor to nullptr here.

Comment 6

[Eric Chou [:ericchou] [:echou]]

(In reply to Blake Kaplan (:mrbkap) [PTO Sep 5-Sep 19] from comment #5)
> Comment on attachment 798801 [details] [diff] [review]
> patch 1: v1: use a pointer to hold a global static variable to avoid
> assertion
> 
> Review of attachment 798801 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: dom/bluetooth/linux/BluetoothDBusService.cpp
> @@ +177,5 @@
> >  static nsTArray<uint32_t> sAuthorizedServiceClass;
> >  static nsString sAdapterPath;
> >  static Atomic<int32_t> sIsPairing(0);
> >  static int sConnectedDeviceCount = 0;
> > +static Monitor* sStopBluetoothMonitor = nullptr;
> 
> I'd probably make this a static nsAutoPtr.
> 
> @@ +189,5 @@
> > +}
> > +
> > +BluetoothDBusService::~BluetoothDBusService()
> > +{
> > +  delete sStopBluetoothMonitor;
> 
> And simply set sStopBluetoothMonitor to nullptr here.

Good point. Thanks!

Comment 7

[Eric Chou [:ericchou] [:echou]]

Attachment: patch 1: final: use a pointer to hold a global static variable to avoid assertion, r=mrbkap

* The final patch

Comment 8

[Eric Chou [:ericchou] [:echou]]

https://hg.mozilla.org/integration/b2g-inbound/rev/6e1ba878682a

Comment 9

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/6e1ba878682a