937074 - [B2G][Helix][BlueTooth][wangyuguo]The device can not hear voice after connect BT headset when calling.

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Bluetooth, defect, P1)

Description

[lecky]

User Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; aff-kingsoft-ciba; .NET4.0C; .NET4.0E; Tablet PC 2.0)

Steps to reproduce:

[B2G version] 
Helix V1.1.0 hd 

[Phenomenon]
The device can not hear voice after connect BT headset when calling.
[repo steps]
A is FFOS test phone , B is another phone
1. B call A;
2. A pick up the call,and can hear voice from receiver;
3. Connect a Philip SHB6110(BT headset) with A;


Actual results:

A can not hear voice after SHB6110 BT connect;


Expected results:

A can hear voice after SHB6110 BT connect;

Comment 1

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

I'd like to take a look. Thanks for reporting.

Comment 2

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

Clear ni? since Gina took the bug. Thanks, Gina.

Comment 3

[lecky]

As we know, this question is only happen on the SHB6110 BT heaset,and the rate is 100%.

Comment 4

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

Can you provide bluetooth air sniffer trace (.cfa file)? Or at least hcidump, we don't have SHB6110, if you think this is bluetooth compatibility bug, we hope you can kindly provide sniffer log or hcidump.

Comment 5

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

If you don't have air sniffer, please get hcidump log.
See: https://wiki.mozilla.org/B2G/Bluetooth
Helpful Debugging Information
 hcidump log

    hcidump is a tool for Bluetooth protocol analysis.
    If you're using release build, hcidump would not be included. Please refer to Bug 828810 comment 7 for the step-by-step about how to get hcidump from release build.
    Take the following steps to get hcidump log:
        1. Turn on Bluetooth
        2 - 1. For headset/car kit issues, please enter adb shell hcidump --ascii -t > hcidump.txt
        2 - 2. For file transferring and other issues, please enter adb shell hcidump --hex -t > hcidump.txt
        3. Do the test
        4. Attach hcidump.txt to the bug 

hcidump snoop log

    It will be easier to debug A2DP/AVRCP profiles using snoop format log.
        To enable it, please enter adb shell hcidump -R -w/data/whatever.cfa , this will dump log into /data/whatever.cfa

Comment 6

[lecky]

Attachment: Bug 937074 attchment 131113-1014.zip

Comment 7

[lecky]

There is two hcidump, one is the philip headset failed, and the other is jabra headset normal.

Comment 8

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

Thanks. lecky. I will take a look first.

Comment 9

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

By checking Philips SHB6 snoop log, I found something interesting.
Packet 168 is trying to establish SCO connection (from host) to headset, and it just established right after BRSF reply, which I believe this is truely abnormal.

	165	Slave	3	AT+BRSF=25.	Retrieve AG Supported Features			24		2013/11/11 上午 07:29:01.803419	
	166	Master	3	..+BRSF: 97..			Retrieved AG Supported Features	26	 00:00:00.074910	2013/11/11 上午 07:29:01.878329	
	167	Master	3	..OK..			Success	19	 00:00:00.000154	2013/11/11 上午 07:29:01.878483	

______________________________________________________
	168	Command	0x0428	Setup_Synchronous_Connection						17	21	 00:00:00.001836	2013/11/11 上午 07:29:01.880319	
	169	Event	0x0428	Setup_Synchronous_Connection	Command Status	Success				4	7	 00:00:00.000887	2013/11/11 上午 07:29:01.881206	
_______________________________________________________

Another strange part is +CIND:5, 1, 0,0,0,0,0.
The service is not available. After packet 238, service indicator is reported.

Comment 10

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

lecky,
In Philips SHB6 log, I did not see the tester has dialed an incoming call, as the description shows the problem shall happen with incoming call. And Jabra case, I do see an incoming call, so I want to make sure the log had captured with the same reproduced steps.

Comment 11

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

(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #10)
> lecky,
> In Philips SHB6 log, I did not see the tester has dialed an incoming call,
> as the description shows the problem shall happen with incoming call. And
> Jabra case, I do see an incoming call, so I want to make sure the log had
> captured with the same reproduced steps.
Sorry please ignore my question.

Comment 12

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

The only problem I can see now is, when it already has an active call, after we connect RFCOMM we did not wait until ACL handshake completed and we recover SCO link as soon as possible.
In Philips case, after BRSF reply finish, we established SCO, later, CIND reports back with 'service state' equals to 0, maybe headset state got confused at that point.
And even the headset does not query AT+CHLD=?.

Comment 13

[lecky]

The headset does not query AT+CHLD is because the SHB6110 does not support 3-way calling.

Comment 14

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

(In reply to lecky from comment #13)
> The headset does not query AT+CHLD is because the SHB6110 does not support
> 3-way calling.
You're right. CHLD is not the problem at all.

Comment 15

[lecky]

I agree with your judgement at command of 9. So we should make sure the command of HandleCallStateChanged is after the AT command of "AT+CMER=" when there is a call.

Comment 16

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

I'm currently working on b2g 1.3 release workweek for bluedroid stack, so I'm not able to provide suggestion during Nov.18-24.

Comment 17

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

Hi lecky,

Since all major Bluetooth contributors (Gina, Shawn and Ben) in Taipei will focus on v1.3 feature this week, I'm going to redirect this bug to Jamin Liu, newcomer to BT team who will be in charge of HFP/HSP, to test with SHB6110 BT headset.

Comment 18

[Wayne Chang [:wchang]]

Eric,

I'd need some opinions on this being a blocker or not. As this currently only happens on this particular headset, can you suggest if this is a problem on the headset or there is something with our BT that we have overlooked?

Thanks.

Comment 19

[lecky]

In fact, I think the code of "NotifyStatusChanged(NS_LITERAL_STRING("bluetooth-hfp-status-changed"))" in file of BluetoothHfpManager.cpp may exit something wrong, I think it is should be send after the AT command of CMER. In fact, the problem is also exit in headset like MOTO S305 and Asteroid Mini.

Comment 20

[lecky]

The state of "bluetooth-hfp-status-changed" is not the reason, though create the ConnectSco in the AT command, and do not establish the ConnectSco in function of HandleCallStateChanged at the prevCallState is nsIRadioInterfaceLayer::CALL_STATE_DISCONNECTED, keep establish the ConnectSco at the prevCallState is nsIRadioInterfaceLayer::CALL_STATE_INCOMING.

Though those modify, we have test pass at heaset of MOTO S305 and Asteroid Mini.Nest we will test the philip heaset.

Comment 21

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

Hi lecky,
Thank you for your valuable information.
I believe we can make a workaround for this bug, however, I want to know better about the root cause for providing a robust solution.

I don't have the headset MOTO S305 and Asteroid Mini, would it be possible for you to tell me which AT command them sent during the reproduction steps? I want to compare the unsupported AT commands these incompatible BT headset and make sure we can fix them all.

Could you choose a way to do the test on MOTO S305 and Asteroid Mini when you have time?
Thank you.
1. Provide bluetooth air sniffer trace (.cfa file) 
 or
2. Turn on BT_WARNING and search for "Unsupported AT command"
 or
3. Put a log print  __android_log_print(ANDROID_LOG_INFO, "geckoHFP", "%s", warningMsg);
   below this line "warningMsg.Append(NS_LITERAL_CSTRING(", reply with ERROR"));" in BluetoothHfpManager.cpp.

Comment 22

[lecky]

Attachment: bug 937074_NEW.zip

Comment 23

[lecky]

In the new attachment:
1.<<130829102706_bt_hcidump_MOTO S305.cfa>> the fifth time happend the problem.
2.<<130830151918_bt_hcidump_Asteroid Mini.cfa>> every time happend the problem.
both above test without any modify in BluetoothHfpManager.cpp 
3.<<Modify for bug 937074.txt>>is my solution on this problem, after merge such modify, both test pass,Please refer.

Comment 24

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

Attachment: [HFP] Make sure SLC established before we set up SCO link

Comment 25

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

Comment on attachment 8335918 [details] [diff] [review]
[HFP] Make sure SLC established before we set up SCO link

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

Hi Jamin, your solution looks ok to me. However I was thinking that maybe we should move the mCMER check into function ConnectSco(), which means that we can block all SCO establish requests and not only the one in HandleCallStateChange().

Comment 26

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

Hi lecky,
Thank you for you help.
If we set up SCO link before SLC established, the SCO link can't work correctly.
If SLC process take too much time between HF and AG, it would cause this bug. (It may happen on some headsets)

I think your modification can prevent this situation and solve the problem.
I added a draft patch ased the same idea of your modification, I'll discuss with my college and make the final patch recently.
Thanks.

Comment 27

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

(In reply to Jamin Liu [:jaliu] from comment #26)
> Hi lecky,
> Thank you for you help.
> If we set up SCO link before SLC established, the SCO link can't work
> correctly.
> If SLC process take too much time between HF and AG, it would cause this
> bug. (It may happen on some headsets)
> 
> I think your modification can prevent this situation and solve the problem.
> I added a draft patch ased the same idea of your modification, I'll discuss
Fix typom  "ased" -> "based on"
> with my college and make the final patch recently.
> Thanks.

Comment 28

[lecky]

Hi Jamin:
   I agree with your modify in attachment of 8335918. 
   And could you tell me the code in function ConnectSco why is
    "mScoSocketStatus = mSocket->GetConnectionStatus();"
not "mScoSocketStatus = mScoSocket->GetConnectionStatus();"?

Comment 29

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

Hi lecky,
I think it should be "mScoSocket->GetConnectionStatus()" rather than "mSocket->GetConnectionStatus()".
I'll fix this issue.
Thank you for your report.

Comment 30

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

Attachment: [HFP] Make sure SLC established before we set up SCO link (patch 2)

Comment 31

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

Comment on attachment 8336615 [details] [diff] [review]
[HFP] Make sure SLC established before we set up SCO link (patch 2)

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

Hi Jamin, please see my comments below. Thanks. :)

::: dom/bluetooth/bluez/BluetoothHfpManager.cpp
@@ +1433,5 @@
>          case nsITelephonyProvider::CALL_STATE_DISCONNECTED:
>            // Incoming call, no break
>            sStopSendingRingFlag = true;
>            ConnectSco();
> +

Please do not leave an extra line. It shouldn't break here so you could add a simple comment such as 

/* continue */

if you want to highlight.

@@ +1803,5 @@
>    }
>  
> +  // Make sure Service Level Connection established before we start to
> +  // set up SCO (synchronous connection).
> +  if (!mCMER) {

Actually, this may not work since mCMER would be possible to be false even after SLC being established. mCMER is a flag representing the last integer of command AT+CMER, not represents if AT+CMER has come.

We may need a new varaible to keep SLC state.

@@ +1805,5 @@
> +  // Make sure Service Level Connection established before we start to
> +  // set up SCO (synchronous connection).
> +  if (!mCMER) {
> +    mConnectScoRequest = true;
> +    BT_WARNING("ConnecteSco called before Service Level Connection established!");

nit: max 80-chars per line, please.

@@ +1817,5 @@
>    BluetoothService* bs = BluetoothService::Get();
>    NS_ENSURE_TRUE(bs, false);
>    nsresult rv = bs->GetScoSocket(mDeviceAddress, true, false, mScoSocket);
>  
> +  mScoSocketStatus = mScoSocket->GetConnectionStatus();

Good catch.

::: dom/bluetooth/bluez/BluetoothHfpManager.h
@@ +99,5 @@
>  
>    bool Listen();
> +  /**
> +   * This function set up a Synchronous Connection (SCO) link for HFP.
> +   * Service Level Connection (SLC) should established before SCO setup process.

nit: should 'be' established

@@ +101,5 @@
> +  /**
> +   * This function set up a Synchronous Connection (SCO) link for HFP.
> +   * Service Level Connection (SLC) should established before SCO setup process.
> +   * If SLC haven't been established, this function will return false and send a
> +   * request to set up SCO ater HfpManager recieve AT+CMER.

typo: receive

Comment 32

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

Attachment: [HFP] Make sure SLC established before we set up SCO link (patch 2)

Comment 33

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

Comment on attachment 8336720 [details] [diff] [review]
[HFP] Make sure SLC established before we set up SCO link (patch 2)

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

LGTM. Thanks.

Comment 34

[lecky]

Hi jamin:
   Is your patch on lix V1.1.0 hd?

Comment 35

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

(In reply to lecky from comment #34)
> Hi jamin:
>    Is your patch on lix V1.1.0 hd?

The patch won't be merged into v1.1 hd unless it's hd+. It depends on the decision of triage.

Comment 36

[lecky]

Hi wayne

   this bug must be resolved in HD+, So please help to process.

Thanks

Comment 37

[Wayne Chang [:wchang]]

Jamin, Eric,

Can you briefly describe:
1> the root cause of this? Is it due to these certain models of BT headsets of is this a fault on b2g side?
2> risk of landing this patch on b2g18 now

Thanks

Comment 38

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

Hi Wayne,
1> Root cause
The Service Level Connection(SLC) should be established before we trigger synchronous connection process.

If user turn on Bluetooth when a telephone call is connected and the hand-free device is slow on SLC process, the bug 
would occur.  I believe it's a bug on Firefox OS side.

2> Risk of landing this patch on b2g18
The fix patch has been pushed to try server for mozilla-central and Eric added a flag HD? for 1.1HD.
I may be more specific on landing time evaluating after I talk to Eric tomorrow. 
Thank you.

Comment 39

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

It looks good on try server.
https://tbpl.mozilla.org/?tree=Try&rev=0da3e0bd4ae5

Comment 40

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

Attachment: [final][Bluetooth] Make sure SLC established before we set up SCO. r=echou

Comment 41

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

https://hg.mozilla.org/integration/b2g-inbound/rev/1f774c175bc0

Comment 42

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

> 2> risk of landing this patch on b2g18 now

Fairly low. The only change would be the timing of establishing the voice link (SCO), and apparently this patch is the right solution.

Comment 43

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/1f774c175bc0

Comment 44

[Jason Smith [:jsmith]]

Mass-modify - removal of no longer relevant blocking flags.