1141899 - [NFC][Bluetooth][Nexus5-L] Could not auto connect NFC headset

Status: VERIFIED FIXED

(Firefox OS Graveyard :: Bluetooth, defect)

Description

[Alison Shiue]

Attachment: nexus_5_nfc_bt.log

Gaia-Rev        5af6f8d5d6161dea02002634c6d0a570a122e5dd
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/ec87adb8cf13
Build-ID        20150310162504
Version         37.0
Device-Name     hammerhead
FW-Release      5.0
FW-Incremental  eng.cltbld.20150310.201846
FW-Date         Tue Mar 10 20:19:04 EDT 2015
Bootloader      HHZ11k

STR:
1. Enable NFC on device
2. Tap NFC-headset on device
3. When BT connect dialog pop-up, press "Yes" to connect to the NFC-headset

Expect result:
NFC headset has been paired and auto connected

Actual result:
NFC headset has been paired but did not auto connect

Comment 1

[bhavana bajaj [:bajaj]]

Allison, does this happen on flame as well or this is nexus 5 specific?

Comment 2

[Alison Shiue]

(In reply to bhavana bajaj [:bajaj] from comment #1)
> Allison, does this happen on flame as well or this is nexus 5 specific?

This issue only happens on Nexus 5.

Comment 3

[bhavana bajaj [:bajaj]]

Shawn, could be help make a judgement if we'd block on this specific nexus - 5 L issue?

Comment 4

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

I will investigate this bug.

Comment 5

[shawn ku [:sku]]

Shawn Huang take this bug (comment 4), remove ni for myself.

Comment 6

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

Can you provide me the device you tested?

Comment 7

[Alison Shiue]

(In reply to Shawn Huang [:shawnjohnjr] from comment #6)
> Can you provide me the device you tested?

Sure. remove ni

Comment 8

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

I saw libfdio timerfd_create failed: Invalid argument.


03-23 14:19:42.593 E/bt-btm  ( 1720): btm_sec_disconnected - Clearing Pending flag
03-23 14:19:42.866 D/NfcNci  (  195): doPresenceCheck
03-23 14:19:42.878 E/HWComposer(  193): Non-uniform vsync interval: 17003802
03-23 14:19:43.494 E/libfdio ( 1720): timerfd_create failed: Invalid argument

Comment 9

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

03-23 18:18:27.310 I/GeckoBluetooth( 4895): CreatePairedDeviceInternal
03-23 18:18:27.310 E/bt-btif ( 4999): check_cod: remote_cod = 0x240404
03-23 18:18:32.442 E/bt-btif ( 4999): Do not find the bg connection mask for the remote device
03-23 18:18:32.442 E/bt-btif ( 4999): check_cod: remote_cod = 0x240404
03-23 18:18:32.672 I/GeckoConsole( 4895): Content JS LOG: [NfcHandoverManager]: Pairing failed 
03-23 18:18:32.672 I/GeckoConsole( 4895):     at _logVisibly (app://system.gaiamobile.org/gaia_build_defer_index.js:1663:0)

Comment 10

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

I enabled more bluedroid logs and found still error, i'm afraid I need to dig into bluedroid stack further.

03-23 18:29:28.822 I/GeckoBluetooth(  190): CreatePairedDeviceInternal: !!!!!!!  Create Bonding !!!!!!!!!
03-23 18:29:28.823 I/bt-btif (  803): btif_dm_create_bond: bd_addr=4c:21:d0:9f:12:f1, transport=0
03-23 18:29:28.823 I/bt-btif (  803): btif_dm_generic_evt: event=33026
03-23 18:29:28.823 D/bt-btif (  803): in, bd addr:4c:21:d0:9f:12:f1, prop type:4, len:4
03-23 18:29:28.823 E/bt-btif (  803): check_cod: remote_cod = 0x240404
03-23 18:29:28.823 D/bt-btif (  803): bond_state_changed: state=1 prev_state=0
03-23 18:29:28.823 I/bt-btif (  803): HAL bt_hal_cbacks->bond_state_changed_cb
03-23 18:29:28.823 I/bt-btm  (  803): BTM_InqDbRead: bd addr [4c21d09f12f1]
03-23 18:29:28.823 D/bt-btm  (  803): btm_find_dev_type - unknown device, BR/EDR assumed
03-23 18:29:28.823 D/bt-btm  (  803): btm_find_dev_type - device_type = 1 addr_type = 0
03-23 18:29:28.823 I/bt-btm  (  803): btm_sec_bond_by_transport BDA: 4c:21:d0:9f:12:f1
03-23 18:29:28.823 D/bt-btm  (  803): btm_sec_bond_by_transport: Transport used 1
03-23 18:29:28.823 I/bt-btm  (  803): btm_find_or_alloc_dev
03-23 18:29:28.823 I/bt-btm  (  803): btm_sec_alloc_dev
03-23 18:29:28.823 I/bt-btm  (  803): BTM_InqDbRead: bd addr [4c21d09f12f1]
03-23 18:29:28.823 D/bt-btm  (  803): BTM_GetHCIConnHandle
03-23 18:29:28.823 D/bt-btm  (  803): BTM_GetHCIConnHandle
03-23 18:29:28.823 D/bt-btm  (  803): before update sec_flags=0x80
03-23 18:29:28.823 I/bt-btm  (  803): BTM: BTM_DeleteStoredLinkKey: delete_all_flag: FALSE
03-23 18:29:28.823 D/bt-btm  (  803): after update sec_flags=0x80
03-23 18:29:28.823 I/bt-btm  (  803):   remote_features page[0] = 00-00-00-00
03-23 18:29:28.823 I/bt-btm  (  803):                               00-00-00-00
03-23 18:29:28.823 I/bt-btm  (  803):   remote_features page[1] = 00-00-00-00
03-23 18:29:28.823 I/bt-btm  (  803):                               00-00-00-00
03-23 18:29:28.823 I/bt-btm  (  803):   remote_features page[2] = 00-00-00-00
03-23 18:29:28.823 I/bt-btm  (  803):                               00-00-00-00
03-23 18:29:28.823 I/bt-btm  (  803): BTM_SecBond: Remote sm4: 0x0  HCI Handle: 0xffff
03-23 18:29:28.823 D/bt-btm  (  803): sec mode: 4 sm4:x0
03-23 18:29:28.823 I/bt-btm  (  803): btm_sec_change_pairing_state  Old: 0
03-23 18:29:28.823 I/bt-btm  (  803): btm_sec_change_pairing_state  New: 1 pairing_flags:0x1
03-23 18:29:28.823 I/bt-btm  (  803): BTM_ReadRemoteDeviceName: bd addr [4c21d09f12f1]
03-23 18:29:28.823 I/bt-btm  (  803): no device found in inquiry db
03-23 18:29:28.823 D/bt-btm  (  803): btm_acl_paging discing:0, paging:0 BDA: 4c21d09f12f1
03-23 18:29:28.823 D/bt-btm  (  803): connecting_bda: 000000000000
03-23 18:29:28.823 I/bt-btm  (  803): btm_find_or_alloc_dev
03-23 18:29:28.823 D/bt-btm  (  803): State:1 sm4: 0x0 sec_state:0
03-23 18:29:29.458 I/bt-btif (  803): BTHF: device_status_notification
03-23 18:29:33.955 I/bt-btm  (  803): BDA 4c:21:d0:9f:12:f1
03-23 18:29:33.955 I/bt-btm  (  803): Inquire BDA 4c:21:d0:9f:12:f1
03-23 18:29:33.955 I/bt-btm  (  803): BTM_InqDbRead: bd addr [4c21d09f12f1]
03-23 18:29:33.955 D/bt-btm  (  803): btm_find_dev_type - device_type = 0 addr_type = 0
03-23 18:29:33.955 I/bt-btm  (  803): btm_sec_rmt_name_request_complete
03-23 18:29:33.955 D/bt-btm  (  803): btm_acl_resubmit_page
03-23 18:29:33.956 I/bt-btm  (  803): Security Manager: rmt_name_complete PairState: 1  RemName:   status: 4 State:0  p_dev_rec: 0xb6bd5ebc 
03-23 18:29:33.956 I/bt-btm  (  803): btm_sec_rmt_name_request_complete() continue bonding sm4: 0x0000, status:0x4
03-23 18:29:33.956 I/bt-btm  (  803): btm_sec_change_pairing_state  Old: 1
03-23 18:29:33.956 I/bt-btm  (  803): btm_sec_change_pairing_state  New: 0 pairing_flags:0x1
03-23 18:29:33.956 I/bt-btm  (  803): BTM_IsAclConnectionUp: RemBdAddr: 4c21d09f12f1
03-23 18:29:33.956 I/bt-btm  (  803): BTM_IsAclConnectionUp: RemBdAddr: 4c21d09f12f1
03-23 18:29:33.956 I/bt-btm  (  803): BTM_IsAclConnectionUp: RemBdAddr: 4c21d09f12f1
03-23 18:29:33.956 I/bt-btm  (  803): BTM_IsAclConnectionUp: RemBdAddr: 4c21d09f12f1
03-23 18:29:33.956 D/bt-btm  (  803): btm_sec_clear_ble_keys: Clearing BLE Keys
03-23 18:29:33.956 I/bt-btm  (  803): BTM: BTM_DeleteStoredLinkKey: delete_all_flag: FALSE
03-23 18:29:33.957 E/bt-btif (  803): Do not find the bg connection mask for the remote device
03-23 18:29:33.957 D/bt-btif (  803): bta_gattc_co_cache_reset()
03-23 18:29:33.967 I/bt-btif (  803): btif_dm_upstreams_cback  ev: BTA_DM_AUTH_CMPL_EVT
03-23 18:29:33.967 D/bt-btif (  803): in, bd addr:4c:21:d0:9f:12:f1, prop type:4, len:4
03-23 18:29:33.968 E/bt-btif (  803): check_cod: remote_cod = 0x240404
03-23 18:29:33.968 D/bt-btif (  803): bond_state_changed: state=0 prev_state=1
03-23 18:29:33.968 I/bt-btif (  803): HAL bt_hal_cbacks->bond_state_changed_cb
03-23 18:29:34.143 I/GeckoConsole(  190): Content JS LOG: [NfcHandoverManager]: Pairing failed

Comment 11

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

Attachment: Comment 10 logcat.txt

Comment 12

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

I just know we're going to move to gonk based on version 5.1. Do we need to verify on gonk v5.1? For me, this looks like bluetooth stack related bug.

Comment 13

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

I'm afraid this will be something caused by lollipop and cannot fix from gecko/gaia.

Comment 14

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

Maybe we should try to test it on device Orion, and see if it can be reproduced.

Comment 15

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

(In reply to Alison Shiue from comment #2)
> (In reply to bhavana bajaj [:bajaj] from comment #1)
> > Allison, does this happen on flame as well or this is nexus 5 specific?
> 
> This issue only happens on Nexus 5.

Alison, I saw different bugs here. on flame-kk, v2.2 gaia nfc module also changed their behaviors. Can we check again on flame-kk for v2.2? I saw if user disconnects headset and use NFC to trigger connection. Connection always fail, but it's a different problem as I saw on Nexus-5-l, perhaps you should use another bug to track.

Comment 16

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

1. On Nexus-5-L, can be paired sometimes but cannot connect with remote device. I will check further for bluetooth stack tomorrow and hopefully I can spot the reason.

2. On flame-kk, can be paired and connect with the remote device at the first time. If the device get paired previously but disconnected, re-connection trigger by nfc never be initialized. I notice that NfcHandoverManager.js is trying to do pairing again even device is in the paired list and I don't see NfcHandoverManager creates connection.

Comment 17

[Alison Shiue]

(In reply to Shawn Huang [:shawnjohnjr] from comment #15)
> (In reply to Alison Shiue from comment #2)
> > (In reply to bhavana bajaj [:bajaj] from comment #1)
> > > Allison, does this happen on flame as well or this is nexus 5 specific?
> > 
> > This issue only happens on Nexus 5.
> 
> Alison, I saw different bugs here. on flame-kk, v2.2 gaia nfc module also
> changed their behaviors. Can we check again on flame-kk for v2.2? I saw if
> user disconnects headset and use NFC to trigger connection. Connection
> always fail, but it's a different problem as I saw on Nexus-5-l, perhaps you
> should use another bug to track.

Yes, this is an issue. I am not sure if 2.1 has the same problem since bug 1146741, I would file another bug to track track this issue. Thank you.

Comment 18

[Jamin Liu [:jaliu][:Jamin]]

Take this bug since Shawn is working on other tasks.

Comment 19

[Jamin Liu [:jaliu][:Jamin]]

Attachment: (for master) Add common profile managers to profile list if Bluetooth CoD of remote device is unclear. (v0)

Comment 20

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

Comment on attachment 8586521 [details] [diff] [review]
(for master) Add common profile managers to profile list if Bluetooth CoD of remote device is unclear. (v0)

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

My concern is that if NFC trigger pairing and COD value is invalid or unexpected, that COD value from bluedroid stack is uninitialized value (because it never had done Inquiry so no extend Inquiry results), it could be anything, so what if that CoD value becomes to expected value but actually wrong value?

::: dom/bluetooth/BluetoothProfileController.h
@@ +52,5 @@
>  
>  // Pointing device: sub-field of minor device class (Bit 7)
>  #define IS_POINTING_DEVICE(cod)      ((GET_MINOR_DEVICE_CLASS(cod) & 0x20) >> 5)
>  
> +// Whether the value of CoD is unexpected. (i.e. Whether Bit 31 ~ Bit 24 = 0x0)

Can you add some extra explanation? It's still unclear to me.

Comment 21

[Jamin Liu [:jaliu][:Jamin]]

Attachment: (for master) Add common profile managers to profile list if Bluetooth CoD of remote device is unclear. (v1)

- Revise previous patch based on #comment 20

Comment 22

[Jamin Liu [:jaliu][:Jamin]]

Attachment: (for master) Add common profile managers to profile list if Bluetooth CoD of remote device is unclear. (v2)

- Fix a typo.

Comment 23

[Jamin Liu [:jaliu][:Jamin]]

(In reply to Shawn Huang [:shawnjohnjr] from comment #16)
> 1. On Nexus-5-L, can be paired sometimes but cannot connect with remote
> device. I will check further for bluetooth stack tomorrow and hopefully I
> can spot the reason.
> 
> 2. On flame-kk, can be paired and connect with the remote device at the
> first time. If the device get paired previously but disconnected,
> re-connection trigger by nfc never be initialized. I notice that
> NfcHandoverManager.js is trying to do pairing again even device is in the
> paired list and I don't see NfcHandoverManager creates connection.

It has been my observation that the issue only happens on nexus-5-L and the root cause is Gecko receiving a invalid CoD(class of device) from Bluetooth stack.

The behaviour of BT stack in flame-kk are different to nexus-5-L, the CoD of headset(SONY-MBH10) is correct in flame-kk. It seems that BlueDroid in nexus-5-L didn't handle CoD of SONY-MBH10 properly, however, Gecko shouldn't fail to connect to the headset even the CoD is abnormal.

In my experiment, nexus-5-L can auto connect to NFC headset normally with the fix #attachment 8586647 [details] [diff] [review].

The auto connect in Flame-kk and nexus-5-L would still fail when user manually disconnect already connected NFC headset. However, the issue is addressed in Bug 1146744 which is going to be fixed.

Comment 24

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

Comment on attachment 8586647 [details] [diff] [review]
(for master) Add common profile managers to profile list if Bluetooth CoD of remote device is unclear. (v2)

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

::: dom/bluetooth/BluetoothProfileController.h
@@ +53,5 @@
>  // Pointing device: sub-field of minor device class (Bit 7)
>  #define IS_POINTING_DEVICE(cod)      ((GET_MINOR_DEVICE_CLASS(cod) & 0x20) >> 5)
>  
> +/**
> + * Whether the value of CoD is invalid. (i.e. Whether Bit 31 ~ Bit 24 != 0x0)

nit: Check whether

Comment 25

[Jamin Liu [:jaliu][:Jamin]]

Attachment: (for master) Add common profile managers to profile list if Bluetooth CoD of remote device is unclear. (v3), r=shuang

Thanks Shawn for reviewing the patch.

Comment 26

[Jamin Liu [:jaliu][:Jamin]]

Attachment: (for 2.2) Add common profile managers to profile list if Bluetooth CoD of remote device is unclear. (v3), r=shuang

Comment 27

[Jamin Liu [:jaliu][:Jamin]]

Comment on attachment 8587251 [details] [diff] [review]
(for 2.2) Add common profile managers to profile list if Bluetooth CoD of remote device is unclear. (v3), r=shuang

[Approval Request Comment]
> Bug caused by (feature/regressing bug #): 
Bug 967345 - Do a BT connect() for a static handover

> User impact if declined: 
Bluetooth headset can't be auto-connected after NFC handover.

> Testing completed: 
- Push to try server
- Follow the STR of this bug with v2.2 build
  Test device: nexus-5-l and Sony MBH10 (NFC/BT headset)

> Risk to taking this patch (and alternatives if risky): 
It's a nexus-5-l specific bug.
I didn't test this patch on flame-L since the image of flame-L isn't ready.

> String or UUID changes made by this patch:
no

Comment 28

[bhavana bajaj [:bajaj]]

waiting for m-c landing here..

Comment 29

[(PTO June 19-July 7) Ryan VanderMeulen]

https://hg.mozilla.org/integration/b2g-inbound/rev/670b9db2b898

Comment 30

[bhavana bajaj [:bajaj]]

Comment on attachment 8587251 [details] [diff] [review]
(for 2.2) Add common profile managers to profile list if Bluetooth CoD of remote device is unclear. (v3), r=shuang

Approving as the m-c merge should happen soon and this can land in parallel

Comment 31

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/670b9db2b898

Comment 32

[(PTO June 19-July 7) Ryan VanderMeulen]

https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/42b4e2547b5f

Comment 33

[Alison Shiue]

Verified on
[2.2]
Build ID               20150419162502
Gaia Revision          c15a2b6d3a783813959c2b3bffd2a131f4270b9e
Gaia Date              2015-04-17 17:49:32
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/cc02ee38b252
Gecko Version          37.0
Device Name            hammerhead
Firmware(Release)      5.1
Firmware(Incremental)  eng.cltbld.20150419.201551
Firmware Date          Sun Apr 19 20:16:07 EDT 2015
Bootloader             HHZ12f

[3.0]
Build ID               20150420160201
Gaia Revision          a8e4f95dce9db727dda5d408b038f97fb4296557
Gaia Date              2015-04-20 19:30:21
Gecko Revision         https://hg.mozilla.org/mozilla-central/rev/e7112314d9d5
Gecko Version          40.0a1
Device Name            hammerhead
Firmware(Release)      5.1
Firmware(Incremental)  eng.cltbld.20150420.192508
Firmware Date          Mon Apr 20 19:25:24 EDT 2015
Bootloader             HHZ12f

Comment 34

[Ben Tian (inactive)]

Device doesn't connect to headset since there's no profile to connect with incorrect cod. The cod update doesn't propagate before the device is created. I'll try to revise the flow.

===
GeckoBluetooth: RemoteDevicePropertiesNotification: 240408   <== got cod update but device isn't created
GeckoBluetooth: BondStateChangedNotification: Bond state: 2 status: 0   <== paired to headset
GeckoBluetooth: ToUint32: major service 1 major device 1f minor device 0
GeckoBluetooth: ConnectDisconnect: aCod 3f00    <== connect gets incorrect (default) cod
GeckoBluetooth: SetupProfiles: cod 3f00: audio 0 rendering 0 peripheral 0 remotecontrol 0 keyboard 0 pointing 0 invalid 0
GeckoBluetooth: StartSession: No queued profile.   <== no profile to connect based on incorrect cod
GeckoBluetooth: EndSession: mSuccess 0

Comment 35

[Ben Tian (inactive)]

Ignore comment 34. It's for bug 1214139.