970148 - [NFC][Bluetooth] NFC-capable bluetooth earphone can't be paired sometimes

Status: RESOLVED FIXED

(Firefox OS Graveyard :: NFC, defect)

Description

[Walter Chen[:ypwalter][:wachen]]

Master branch (V1.4) code - 2014/2/7
Mako device

Steps:
1. Launch "Settings" app
2. Enable "NFC" settings
3. Tap the phone with bluetooth earphone

Expected result:
The bluetooth turned on, and the earphone connected

Actual result:
Bluetooth turned on and NFC paired, but earphone is not connected

I think it might be Bluetooth error.

Comment 1

[Walter Chen[:ypwalter][:wachen]]

There are currently two nfc-capable bt earphone. One set is in BT team for investigation, and another is owned by Dimi for investigation.

Comment 2

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

I think it's a regression bug of NFC component.
I can reproduce this bug on PVT build [1], however, it work fine about 10 days ago.
P.S. I use shadow flash to flash gecko/gaia only.

I think the PVT build [2] is the last build which is not broken.

[1] https://pvtbuilds.mozilla.org/pvt/mozilla.org/b2gotoro/nightly/mozilla-central-mako/2014/02/2014-02-09-04-02-04/
[2] https://pvtbuilds.mozilla.org/pvt/mozilla.org/b2gotoro/nightly/mozilla-central-mako/2014/02/2014-02-01-16-02-01

In normal case, if you use NFC support FxOS phone to tap other NFC device, the phone would vibrate and send few adb logs [3]. (Please check the log below.)
The phone wouldn't vibrate and wouldn't print any log in my test since 2014/02/01.
It seems NFC didn't notice the other device.

The same behavior could be reproduced on NFC earphone or other kind of NFC device, such as Nexus 7.

[3] The log during NFC tapping.
D/BroadcomNfc(  179): NfcTag::setActivationState: state=2
D/BroadcomNfc(  179): pn544InteropIsBusy: 0
D/BroadcomNfc(  179): NfcTag::IsSameKovio: enter
D/BroadcomNfc(  179): NfcTag::discoverTechnologies (activation): enter
D/BroadcomNfc(  179): NfcTag::discoverTechnologies (activation): index=0; tech=1; handle=1; nfc type=2
D/BroadcomNfc(  179): NfcTag::discoverTechnologies (activation): index=1; tech=9; handle=1; nfc type=2
D/BroadcomNfc(  179): NfcTag::discoverTechnologies (activation): exit
D/BroadcomNfc(  179): NfcTag::createNfcTag: enter
D/BroadcomNfc(  179): NfcTag::fillNfcTagMembers1
D/BroadcomNfc(  179): NfcTag::fillNfcTagMembers2
D/BroadcomNfc(  179): NfcTag::fillNfcTagMembers3: index=0; rf tech params mode=0
D/BroadcomNfc(  179): NfcTag::fillNfcTagMembers3: tech A
D/BroadcomNfc(  179): NfcTag::fillNfcTagMembers3: index=1; rf tech params mode=0
D/BroadcomNfc(  179): NfcTag::fillNfcTagMembers3: tech A
D/BroadcomNfc(  179): NfcTag::fillNfcTagMembers4: index=0
D/BroadcomNfc(  179): NfcTag::fillNfcTagMembers4: T2T; tech A
D/BroadcomNfc(  179): NfcTag::fillNfcTagMembers4: index=1
D/BroadcomNfc(  179): NfcTag::fillNfcTagMembers4: T2T; tech A
D/BroadcomNfc(  179): NfcTag::fillNfcTagMembers5: tech A
D/BroadcomNfc(  179): NfcTag::createNfcTag: try notify nfc service
D/nfcd    (  179): static void NfcService::notifyTagDiscovered(INfcTag*): enter
D/BroadcomNfc(  179): NfcTag::createNfcTag: exit
D/nfcd    (  179): void* NfcService::eventLoop(): NFCService msg=3
D/BroadcomNfc(  179): connectWithStatus: Connect to a tech with a different handle
D/BroadcomNfc(  179): doConnect: targetHandle = 0
D/BroadcomNfc(  179): doConnect() Nfc type = 2, do nothing for non ISO_DEP
D/BroadcomNfc(  179): doConnect: exit 0x0
I/BroadcomNfc(  179): Connect Succeeded! (status = 0)
D/BroadcomNfc(  179): NfcTag::isMifareUltralight: return=1
D/BroadcomNfc(  179): doIsNdefFormatable: is formattable=1
D/BroadcomNfc(  179): doCheckNdef: enter
D/BroadcomNfc(  179): doCheckNdef: try NFA_RwDetectNDef
D/BroadcomNfc(  179): doCheckNdefResult: flag formatted for ndef
D/BroadcomNfc(  179): doCheckNdefResult: flag ndef supported
D/BroadcomNfc(  179): doCheckNdef: exit; status=0x0
I/BroadcomNfc(  179): Check Succeeded! (status = 0)
D/BroadcomNfc(  179): doRead: enter
D/BroadcomNfc(  179): ndefHandlerCallback: event=1, eventData=0xb674ea0c
D/BroadcomNfc(  179): ndefHandlerCallback: NFA_NDEF_DATA_EVT; data_len = 77
D/BroadcomNfc(  179): doReadCompleted: status=0x0; is reading=1
D/BroadcomNfc(  179): doRead: read 77 bytes
D/BroadcomNfc(  179): doRead: exit
D/nfcd    (  179): processNotificaton notification=2001
D/nfcd    (  179): numRecords=2
D/nfcd    (  179): tnf=1
D/nfcd    (  179): typeLength=2
D/nfcd    (  179): idLength=0
D/nfcd    (  179): payloadLength=10
D/nfcd    (  179): mPayload 0 = 18
D/nfcd    (  179): mPayload 1 = 209
D/nfcd    (  179): mPayload 2 = 2
D/nfcd    (  179): mPayload 3 = 4
D/nfcd    (  179): mPayload 4 = 97
D/nfcd    (  179): mPayload 5 = 99
D/nfcd    (  179): mPayload 6 = 1
D/nfcd    (  179): mPayload 7 = 1
D/nfcd    (  179): mPayload 8 = 48
D/nfcd    (  179): mPayload 9 = 0
D/nfcd    (  179): tnf=2
D/nfcd    (  179): typeLength=32
D/nfcd    (  179): idLength=1
D/nfcd    (  179): payloadLength=25
D/nfcd    (  179): mPayload 0 = 25
D/nfcd    (  179): mPayload 1 = 0
D/nfcd    (  179): mPayload 2 = 164
D/nfcd    (  179): mPayload 3 = 211
D/nfcd    (  179): mPayload 4 = 94
D/nfcd    (  179): mPayload 5 = 183
D/nfcd    (  179): mPayload 6 = 3
D/nfcd    (  179): mPayload 7 = 144
D/nfcd    (  179): mPayload 8 = 11
D/nfcd    (  179): mPayload 9 = 9
D/nfcd    (  179): mPayload 10 = 80
D/nfcd    (  179): mPayload 11 = 97
D/nfcd    (  179): mPayload 12 = 114
D/nfcd    (  179): mPayload 13 = 114
D/nfcd    (  179): mPayload 14 = 111
D/nfcd    (  179): mPayload 15 = 116
D/nfcd    (  179): mPayload 16 = 32
D/nfcd    (  179): mPayload 17 = 90
D/nfcd    (  179): mPayload 18 = 105
D/nfcd    (  179): mPayload 19 = 107
D/nfcd    (  179): mPayload 20 = 4
D/nfcd    (  179): mPayload 21 = 13
D/nfcd    (  179): mPayload 22 = 4
D/nfcd    (  179): mPayload 23 = 4
D/nfcd    (  179): mPayload 24 = 32
D/nfcd    (  179): void NfcIpcSocket::writeToOutgoingQueue(uint8_t*, size_t) enter, data=0xb800e4b0, dataLen=136
D/nfcd    (  179): Writing 136 bytes to gecko 
I/Gecko   (  177): Nfc Worker: NFC_NOTIFICATION_TECH_DISCOVERED
I/Gecko   (  177): Nfc Worker: numOfRecords = 2
D/BroadcomNfc(  179): doPresenceCheck
I/Gecko   (  177): -*- ObjectWrapper is deprecated. Use Components.utils.cloneInto() instead.
I/Gecko   (  177): ############################### browserElementPanning.js loaded
I/Gecko   (  177): ######################## BrowserElementChildPreload.js loaded
I/Gecko   (  177): -*- ObjectWrapper is deprecated. Use Components.utils.cloneInto() instead.
I/Gecko   (  177): -*- ObjectWrapper is deprecated. Use Components.utils.cloneInto() instead.
I/Gonk    (  177): Setting nice for pid 1064 to 18
I/Gonk    (  177): Changed nice for pid 1064 from 0 to 18.
I/Gonk    (  177): Setting nice for pid 862 to 18
I/Gonk    (  177): Changed nice for pid 862 from 18 to 18.
I/Gonk    (  177): Setting nice for pid 1064 to 18
I/Gonk    (  177): Changed nice for pid 1064 from 18 to 18.
E/Profiler( 1064): BEGIN mozilla_sampler_init
E/Profiler( 1064): BPUnw: [1 total] thread_register_for_profiling(me=0xb6fc2ffc, stacktop=0xbefeef7f)
E/Profiler( 1064): SPS:
E/Profiler( 1064): SPS: Unwind mode       = pseudo
E/Profiler( 1064): SPS: Sampling interval = 0 ms (zero means "platform default")
E/Profiler( 1064): SPS: Entry store size  = 0 (zero means "platform default")
E/Profiler( 1064): SPS: UnwindStackScan   = 0 (max dubious frames per unwind).
E/Profiler( 1064): SPS: Use env var MOZ_PROFILER_MODE=help for further information.
E/Profiler( 1064): SPS:
E/Profiler( 1064): Registering start signal
E/GeckoConsole( 1064): Could not read chrome manifest 'file:///system/b2g/chrome.manifest'.
D/BroadcomNfc(  179): doPresenceCheck
I/Gecko   (  177): -*- ObjectWrapper is deprecated. Use Components.utils.cloneInto() instead.
D/BroadcomNfc(  179): doPresenceCheckResult: sCountTagAway=1
D/BroadcomNfc(  179): NfcTag::setDeactivationState: state=0
D/BroadcomNfc(  179): NfcTag::resetTechnologies
D/BroadcomNfc(  179): doAbortWaits
I/Gecko   ( 1064): ###################################### forms.js loaded
I/Gecko   ( 1064): ############################### browserElementPanning.js loaded
I/Gecko   ( 1064): ######################## BrowserElementChildPreload.js loaded
E/Sandbox ( 1064): install_syscall_filter() failed
I/Gecko   ( 1064): ###################################### forms.js loaded
I/Gecko   ( 1064): ############################### browserElementPanning.js loaded
I/Gecko   ( 1064): ######################## BrowserElementChildPreload.js loaded
D/BroadcomNfc(  179): doPresenceCheck
D/BroadcomNfc(  179): doPresenceCheck: tag already deactivated
D/BroadcomNfc(  179): doDisconnect: enter
D/BroadcomNfc(  179): doDisconnect: tag already deactivated
D/BroadcomNfc(  179): doDisconnect: exit
D/nfcd    (  179): static void NfcService::notifyTagLost(): enter
D/nfcd    (  179): void* NfcService::eventLoop(): NFCService msg=4
D/nfcd    (  179): processNotificaton notification=2002
D/nfcd    (  179): void NfcIpcSocket::writeToOutgoingQueue(uint8_t*, size_t) enter, data=0xb800e6d0, dataLen=8
D/nfcd    (  179): Writing 8 bytes to gecko 
I/Gecko   (  177): Nfc Worker: NFC_NOTIFICATION_TECH_LOST
I/Gecko   (  177): Nfc Worker: sessionId = 1
I/Gecko   (  177): -*- ObjectWrapper is deprecated. Use Components.utils.cloneInto() instead.
I/Gecko   (  177): -*- ObjectWrapper is deprecated. Use Components.utils.cloneInto() instead.

Comment 3

[Ken Chang[:kenkai]]

Sid, may you please check what is happened?

Comment 4

[Walter Chen[:ypwalter][:wachen]]

I don't know if this is fixed. However, there should be someone looking into this bug. :P

Comment 5

[psiddh]

Hi Walter, We made a quick test today with bluetooth speaker (Mini Boom) and observed that pairing happens successfully. Requesting you to please test this scenario on the latest builds.

Comment 6

[Walter Chen[:ypwalter][:wachen]]

I just tried with yesterday's pvt build (standard build, master branch). It didn't even get the phone paired with the earphone. (Sony MH10)

Comment 7

[arno]

I will do some tests with a Motorola headset tomorrow. I find it strange that you have troubles with the Sony earpiece. Forgive the question: you did put the earpiece in pairing mode, right?

Comment 8

[Yoshi Cheng-Hao Huang [:allstars.chh][:allstarschh][:yoshi]]

I'll try with Walter.

Comment 9

[Yoshi Cheng-Hao Huang [:allstars.chh][:allstarschh][:yoshi]]

Attachment: nfc_bt_ear_phone_log.txt

log for the NDEF came from the BT-headset.

From this log, the NDEF is 
tnf: 2 (MIME_MEDIA)
type: application/vnd.bluetooth.ep.oob

I think you didn't handle this case in nfc_manager.

Comment 10

[arno]

(In reply to Yoshi Huang[:allstars.chh] from comment #9)
> log for the NDEF came from the BT-headset.
> 
> From this log, the NDEF is 
> tnf: 2 (MIME_MEDIA)
> type: application/vnd.bluetooth.ep.oob

we do handle this record type:
https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/nfc_manager_utils.js#L163

Since we don't have that particular headset, could you please enable debugging in both NFCManager and NFCHandoverManager? The static handover should be recognized here:
https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/nfc_manager.js#L293

Comment 11

[Yoshi Cheng-Hao Huang [:allstars.chh][:allstarschh][:yoshi]]

(In reply to arno from comment #10)
> > log for the NDEF came from the BT-headset.
> > 
> > From this log, the NDEF is 
> > tnf: 2 (MIME_MEDIA)
> > type: application/vnd.bluetooth.ep.oob
> 
> we do handle this record type:
> https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/
> nfc_manager_utils.js#L163
> 
No, you don't handle this.
I've checked yesterday,
check the calling sequence to see the callers of this function.

nfc_manager checks in https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/nfc_manager.js#L293 
and 
https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/nfc_manager.js#L299

However the tnf here is MIME_MEDIA.
So the NDEF is never being parsed at all.

> Since we don't have that particular headset, could you please enable
> debugging in both NFCManager and NFCHandoverManager? The static handover
> should be recognized here:
> https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/nfc_manager.
> js#L293

The log attached is already with DEBUG enabled by these fileds.
It's all the log you could get.

Comment 12

[arno]

Section 3.2.2 (which describes the NDEF Handover Select Record) of the Connection Handover spec (NFCForum-TS-ConnectionHandover_1_2.doc) states:
'The NFC Forum Well Known Type [NDEF], [NFC RTD] for the Handover Select record is “Hs”'

Note that it says *well known type* with an RTD of 'Hs' to identify a Handover Select Record. This is tested here:
https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/nfc_manager.js#L295

Where did we misinterpret the specs? It feels wrong to check TNF for both well known and media type since this is not consistent with the specs.

Comment 13

[Yoshi Cheng-Hao Huang [:allstars.chh][:allstarschh][:yoshi]]

> (In reply to arno from comment #12)
> 
> Where did we misinterpret the specs? It feels wrong to check TNF for both
> well known and media type since this is not consistent with the specs.

Please check 
http://members.nfc-forum.org/resources/AppDocs/NFCForum_AD_BTSSP_1_0.pdf 
Section 4.2.1 Simplified Tag Format for a Single Bluetooth Carrier

Comment 14

[arno]

Good catch. That case we don't handle indeed. I'll prepare a patch. Thanks for pointing this out.

Comment 15

[arno]

Attachment: Add support for simple pairing record

Yoshi: this PR should implement the simple pairing record. We don't have any BT devices that use this simplified pairing record. If you have a minute, could you please see if you can connect with the headset you've been using? TIA

Comment 16

[Yoshi Cheng-Hao Huang [:allstars.chh][:allstarschh][:yoshi]]

Comment on attachment 8409891 [details] [review]
Add support for simple pairing record

I've pasted the raw data before, please use that as the test data for your unit test first, once the test is passed and travis is green, then please ask QA or me to help veriy this.

Comment 17

[Yoshi Cheng-Hao Huang [:allstars.chh][:allstarschh][:yoshi]]

Comment on attachment 8409891 [details] [review]
Add support for simple pairing record

Just tried with your patch, and the pairing works.

Comment 18

[arno]

(In reply to Yoshi Huang[:allstars.chh] from comment #17)
> Comment on attachment 8409891 [details] [review]
> Add support for simple pairing record
> 
> Just tried with your patch, and the pairing works.

Thanks for testing. I will add a unit test based on the log you posted once Bug 969277 has landed.

Comment 19

[arno]

Attachment: Add support for simple pairing record

Yoshi: this PR contains two commits as I needed some functionality of Bug 969277 that has been r+'ed by Alive but that hasn't been merged yet. I integrated the pairing UI and also added a unit test for the simplified pairing record.

Comment 20

[arno]

Bug 969277 has landed. I rebased this PR.

Comment 21

[(inactive after 6/18) Alive Kuo [:alive]]

Comment on attachment 8415473 [details] [review]
Add support for simple pairing record

Please remove unwanted restore()

Comment 22

[arno]

Attachment: Add support for simple pairing record. r=alive

Fixed Alive's nits.

Comment 23

[Ryan VanderMeulen [:RyanVM]]

Master: https://github.com/mozilla-b2g/gaia/commit/4af716f09747edfbea637f5b60f7fd7d0183f19b