1120889 - [Flame][Bluetooth] Device pairing fails while we share audio via Bluetooth in Music.

Status: RESOLVED WORKSFORME

(Firefox OS Graveyard :: Bluetooth, defect)

Description

[Paladin]

Attachment: logcat_flame_0203.txt

[1.Description]:
[Flame][v2.2][Bluetooth] With no paired devices in Bluetooth, device pairing fails when we share audio via Bluetooth in Music.
Attachment: logcat_flame_0203.txt and pair_fail.3gp
Occurrence time: 02:03

[2.Testing Steps]: 
Set up: There is no paired devices in Bluetooth.
1. Open Music.
2. Play an audio.
3. Tap Share button and select bluetooth item.
4. The Turn on bluetooth page pop up and tap Ok button.
5. The Bluetooth page pops up.
6. Tap any device in "Devices in the area" section.


[3.Expected Result]: 
Device should be successfully paired.

[4.Actual Result]: 
5. "Pairing with device..." prompt is appear, but device  display it a long time and no any prompt.

[5.Reproduction build]: 
Flame 2.1 build:
Gaia-Rev        1975241ac29f723479e6c60b2bf74ebed54da91a
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/0863fe4b75c3
Build-ID        20150112001215
Version         34.0
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.cltbld.20150112.035023
FW-Date         Mon Jan 12 03:50:34 EST 2015
Bootloader      L1TC000118D0

Flame 2.2 build:
Gaia-Rev        7c5b27cad370db377b18a742d3f3fdb0070e899f
Gecko-Rev       https://hg.mozilla.org/re

[6.Reproduction Frequency]: 
Always Recurrence,5/5

[7.TCID]: 
Free Test

Comment 1

[Paladin]

Attachment: pair_fail.3gp

Comment 2

[Paladin]

Update Flame 2.2 info,
Flame 2.2 build:
Gaia-Rev        f5e481d4caf9ffa561720a6fc9cf521a28bd8439
Gecko-Rev       https://hg.mozilla.org/mozilla-central/rev/bb8d6034f5f2
Build-ID        20150112010228
Version         37.0a1
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.cltbld.20150112.043144
FW-Date         Mon Jan 12 04:31:56 EST 2015

Comment 3

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Paladin,
Which device do you use for testing as the remote device?
Are you using two flame devices to test with?

Comment 4

[Paladin]

Hi Shawn,
We used MX3 and Flame as the remote device.

Comment 5

[Bruce Sun [:brsun]]

I am not able to reproduce this issue on v2.1 (20150112001215 or latest):
[v2.1]
Gaia      0b840c5b94ba08a6169765512f1b2dc8c926b5a9
Gecko     https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/b43ce4e5af1f
BuildID   20150126161201
Version   34.0
ro.build.version.incremental=eng.cltbld.20150126.194107
ro.build.date=Mon Jan 26 19:41:18 EST 2015

Although this issue is not 100% reproducible on my environment, I see the same issue on v2.2 and master:
[v2.2]
Gaia      cc88f3c3ffaef71a15f34e16e5cc17f289683dcc
Gecko     https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/db9a9e77ebea
BuildID   20150126162505
Version   37.0a2
ro.build.version.incremental=eng.cltbld.20150126.200627
ro.build.date=Mon Jan 26 20:06:38 EST 2015
[master]
Gaia      b02ec9713e6de8d96c6954d2c0dfd0442b0656ac
Gecko     https://hg.mozilla.org/mozilla-central/rev/38e4719e71af
BuildID   20150126160233
Version   38.0a1
ro.build.version.incremental=eng.cltbld.20150126.192457
ro.build.date=Mon Jan 26 19:25:08 EST 2015

Thanks :btian, this issue might be related to bug 1122177. We might need to do more investigation on this to make sure about it.

Comment 6

[Bruce Sun [:brsun]]

This issue can be reproduced if |ro.moz.bluetooth.backend=bluedroid|.

Comment 7

[Bruce Sun [:brsun]]

|BluetoothServiceBluedroid::BondStateChangedNotification()| receives |STATUS_FAIL| as |aStatus| in this case.

Comment 8

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

When bluetooth stack is going to pair with the remote device, I saw very strange behavior.
Frame 80~82, name request was been issued and less 200ms, i saw cancel command issued again.
After name request has been canceled, disconnection was been made.


	75	Command	0x0402	Inquiry_Cancel						0	4	 00:00:00.862200	2015/1/27 上午 09:40:30.333841	
	76	Event	0x0402	Inquiry_Cancel	Command Complete	Success				4	7	 00:00:00.001889	2015/1/27 上午 09:40:30.335730	
	77	Command	0x0c12	Delete_Stored_Link_Key						7	11	 00:00:00.006949	2015/1/27 上午 09:40:30.342679	
	78	Event	0x0c12	Delete_Stored_Link_Key	Command Complete	Success				6	9	 00:00:00.002480	2015/1/27 上午 09:40:30.345159	
	79	Command	0x0419	Remote_Name_Request						10	14	 00:00:00.000761	2015/1/27 上午 09:40:30.345920	
	80	Event	0x0419	Remote_Name_Request	Command Status	Success				4	7	 00:00:00.000951	2015/1/27 上午 09:40:30.346871	
	81	Command	0x041a	Remote_Name_Request_Cancel						6	10	 00:00:00.000801	2015/1/27 上午 09:40:30.347672	
	82	Event			Remote Name Request Complete	Connection Terminated by Local Host				255	258	 00:00:00.000694	2015/1/27 上午 09:40:30.348366	
	83	Event			Disconnection Complete	Success	0x0002			4	7	 00:00:00.005923	2015/1/27 上午 09:40:30.354289	
	84	Event	0x041a	Remote_Name_Request_Cancel	Command Complete	Success				10	13	 00:00:00.001219	2015/1/27 上午 09:40:30.355508

Comment 9

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to Bruce Sun [:brsun] from comment #7)
> |BluetoothServiceBluedroid::BondStateChangedNotification()| receives
> |STATUS_FAIL| as |aStatus| in this case.

That makes sense, because bluetooth stack even doesn't start authentication process. So the result code is STATUS_FAIL instead of AUTH_FAIL. Getting remote name is part of pairing procedure. But it stopped in the middle of procedure.

Comment 10

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Two things I think we shall do, 
1. Correctly STATUS_FAIL return code, so at least UI will refresh and update instead of stocking at the pairing status.
2. Find out why it's so easy to fail in the middle of getting the remote device name.

Comment 11

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

After reviewing the fail case logs, I found something interesting:
When we try to pair with the remote device:
1. StopDiscovery executed
2. CreateBond executed
3. stack is going to cancel inquiry 
4. Cancel remote device name after Inquiry
5. btif_dm_upstreams_cback  ev: BTA_DM_BUSY_LEVEL_EVT
6. Discover state changed
7. Connection Terminated by local host (due to get remote name failed)

I suspect this is related to two operation was mixed together and cause problem.
It's fine to stop discovery before pairing with the remote devices. However, we did not wait for discovery state changed and immediately pair with the remote devices. This creates unexpected behaviour. If stop discovery procedure completed before pairing, pairing failure might not happen.

Comment 12

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to Shawn Huang [:shawnjohnjr] from comment #11)
> After reviewing the fail case logs, I found something interesting:
> When we try to pair with the remote device:
> 1. StopDiscovery executed
> 2. CreateBond executed
> 3. stack is going to cancel inquiry 
> 4. Cancel remote device name after Inquiry
> 5. btif_dm_upstreams_cback  ev: BTA_DM_BUSY_LEVEL_EVT
> 6. Discover state changed
> 7. Connection Terminated by local host (due to get remote name failed)
> 
> I suspect this is related to two operation was mixed together and cause
> problem.
> It's fine to stop discovery before pairing with the remote devices. However,
> we did not wait for discovery state changed and immediately pair with the
> remote devices. This creates unexpected behaviour. If stop discovery
> procedure completed before pairing, pairing failure might not happen.

I guess the previous StopDisocvery operation can cause the next operation 'CreateBond' fail.
Since these operations are async, so we cannot assume it's safe to perform two operations at the same time.

Comment 13

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

#0  BTM_CancelRemoteDeviceName () at external/bluetooth/bluedroid/stack/./btm/btm_inq.c:1118
#1  0xb6d3271c in bta_dm_search_cancel_notify (p_data=p_data@entry=0x0) at external/bluetooth/bluedroid/bta/./dm/bta_dm_act.c:2232
#2  0xb6d32780 in bta_dm_search_cancel (p_data=<optimized out>) at external/bluetooth/bluedroid/bta/./dm/bta_dm_act.c:1318
#3  0xb6d33ea6 in bta_dm_search_sm_execute (p_msg=0xb8602c64) at external/bluetooth/bluedroid/bta/./dm/bta_dm_main.c:361
#4  0xb6d4149c in bta_sys_event (p_msg=0xb8602c64) at external/bluetooth/bluedroid/bta/./sys/bta_sys_main.c:504
#5  0xb6d6f0cc in btu_task (param=<optimized out>) at external/bluetooth/bluedroid/stack/./btu/btu_task.c:552
#6  0xb6d2dd7e in gki_task_entry (params=3068780972) at external/bluetooth/bluedroid/gki/./ulinux/gki_ulinux.c:157
#7  0xb6f1222c in __thread_entry (func=0xb6d2dd21 <gki_task_entry>, arg=0xb6e9e1ac <gki_pthread_info>, tls=0xb63c2dd0) at bionic/libc/bionic/pthread_create.cpp:105
#8  0xb6f123c4 in pthread_create (thread_out=0xb6e9ce18 <gki_cb+4>, attr=<optimized out>, start_routine=0xb6d2dd21 <gki_task_entry>, arg=0x78) at bionic/libc/bionic/pthread_create.cpp:224
#9  0x00000000 in ?? ()

Comment 14

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

#0  BTM_CancelRemoteDeviceName () at external/bluetooth/bluedroid/stack/./btm/btm_inq.c:1118
#1  0xb6d33eba in bta_dm_search_sm_execute (p_msg=0xb8602cfc) at external/bluetooth/bluedroid/bta/./dm/bta_dm_main.c:361
#2  0xb6d4149c in bta_sys_event (p_msg=0xb8602cfc) at external/bluetooth/bluedroid/bta/./sys/bta_sys_main.c:504
#3  0xb6d6f0cc in btu_task (param=<optimized out>) at external/bluetooth/bluedroid/stack/./btu/btu_task.c:552
#4  0xb6d2dd7e in gki_task_entry (params=3068780972) at external/bluetooth/bluedroid/gki/./ulinux/gki_ulinux.c:157
#5  0xb6f1222c in __thread_entry (func=0xb6d2dd21 <gki_task_entry>, arg=0xb6e9e1ac <gki_pthread_info>, tls=0xb63c2dd0) at bionic/libc/bionic/pthread_create.cpp:105
#6  0xb6f123c4 in pthread_create (thread_out=0xb6e9ce18 <gki_cb+4>, attr=<optimized out>, start_routine=0xb6d2dd21 <gki_task_entry>, arg=0x78) at bionic/libc/bionic/pthread_create.cpp:224

Comment 15

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Maybe I was wrong, it's not related to stop discovery. But it must be related to get remote device name.

Comment 16

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Strange, I flashed today's PVT build. Now this bug cannot be reproduced.

Comment 17

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to Bruce Sun [:brsun] from comment #5)
> Thanks :btian, this issue might be related to bug 1122177. We might need to
> do more investigation on this to make sure about it.
Maybe we shall check if we can reproduce in bug 1122177. In the beginning, we suspect it's related to changing priority which makes bug appear (maybe it's related to timing), but now this bug is hard to reproduce in bug 1120889.

Comment 18

[Bruce Sun [:brsun]]

(In reply to Shawn Huang [:shawnjohnjr] from comment #16)
> Strange, I flashed today's PVT build. Now this bug cannot be reproduced.

Probably this is because those patches on bug 1081871 has been backed out [1][2][3].

[1] http://hg.mozilla.org/mozilla-central/rev/59452425e446
[2] https://bugzilla.mozilla.org/show_bug.cgi?id=1081871#c32
[3] https://hg.mozilla.org/mozilla-central/rev/800c5cb0f4d9

Comment 19

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

That will be interesting!
Bug 1081871 - Evaluate using cgroups instead of nice values for prioritizing processes

It looks like problem disappeared after backed out.

As comment C11 mentioned,
https://bugzilla.mozilla.org/show_bug.cgi?id=1122177#c11
"Prior to the patch we used nice values to adjust the priority of our content processes; after the patch the same is done using Linux control groups which rely on a completely different kernel subsystem."

It looks like changing process priority can hit this bug (even we switch back to non bluetooth daemon architecture).

Comment 20

[Gabriele Svelto [:gsvelto]]

Shawn, shall we close this now that bug 1081871 has been backed out? I'm going to re-land it pref'd off so we can reopen this in case we encounter it again.

Comment 21

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

Sure. I will change it to WFM.