1003472 - [B2G][Gaia][Bluetooth] Pairing with a device inline can cause an pairing error message to appear even if the devices paired successfully.

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Bluetooth, defect)

Description

[Lionel Mauritson]

Attachment: Bluetooth.zip

Description:
When sending an image from the gallery to a device that has not been paired with before an error message can appear even if the devices paired successfully and the file was sent.

Repro Steps:
1) Update a Open_C to BuildID: 20140428000206.
2) Open the Gallery app and select a photo.
3) Select share and then Bluetooth.
4) Select a device that is currently not paired with the DUT.

Actual:
An error message can occur stating that pairing failed either in notification or fullscreen popup form.
The image can be sent regardless and the device will show as paired in the list.

Expected:
If pairing is successful no error message is displayed.

1.4F Environmental Variables:
Device: Open_C 1.4F
BuildID: 20140428000206
Gaia: d23e479e8a4ce0bc620acb2d7e2f82801aa4d0ea
Gecko: 36f67ce46855
Version: 30.0a2
Firmware Version: P821A10-ENG_20140410

Repro frequency: 75%
Link to failed test case: https://moztrap.mozilla.org/manage/case/10157/
See attached: http://youtu.be/wbrLUCIqgBY & logcat

Comment 1

[Lionel Mauritson]

DOES occur on Buri 1.4
1.4 Environmental Variables:
Device: Buri 1.4 MOZ
BuildID: 20140428000206
Gaia: d23e479e8a4ce0bc620acb2d7e2f82801aa4d0ea
Gecko: 36f67ce46855
Version: 30.0a2
Firmware Version: v1.2-device.cfg

Does NOT occur on Buri 1.3
1.3 Environmental Variables:
Device: Buri 1.3 MOZ
BuildID: 20140428024001
Gaia: 32a9e3db738e0b3bc44a4d4d5c16512a2617a2cf
Gecko: d7b1e90008e5
Version: 28.0
Firmware Version: v1.2-device.cfg

Comment 2

[Jason Smith [:jsmith]]

This is confusing UX - this is saying that the file transfer failed, when in reality it worked correctly.

Comment 3

[Kai-Chih Hu [:khu]]

Hi, Tim, since you're the owner for this component(please correct me if I am wrong), can you help to find someone to check this bug? Thanks!

Comment 4

[Kai-Chih Hu [:khu]]

I was wondering, if it's a timing issue? In the video, at 49 sec(http://youtu.be/wbrLUCIqgBY?t=49s), it looks like the error message was received 'before' the file was transferred. From the notification bar, we can see the latest message indicated that, the file can be transferred. Maybe the previous error message was popped up before the paring process?

Comment 5

[[e-mail], [e-mail]]

As comment 4, I suspect this is a timing issue since I have not seen the error log exactly. The two notifications are fired in system/js/bluetooth_transfer.js. One is coming from IAC message(Bluetooth app --> System app). The other is coming from system message.

Notification title - Trigger event
========================================
The transfer has started - (iac-bluetoothTransfercomms)(IAC)
File could not be sent - (bluetooth-opp-transfer-complete)(system message)

According to the recorder, notification "File could not be sent" was received 'before' notification 'The transfer has started'. It means that the IAC message might be received 'after' system message. So that we see this order is reversed, and it could be confused a user. But I believe that the file was not transferred successfully. Because the system message 'bluetooth-opp-transfer-complete' should be coming after we have done 'defaultAdapter.sendFile'. Somehow, the message was showing and comply with the real situation.

=== My test environment ===
Gaia      bac831d2ebc567f0939e41fbd8a4c15ef183b954
Gecko     https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/8040ccd0d4b1
BuildID   20140507000202
Version   30.0
ro.build.version.incremental=eng.cltbld.20140507.042907
ro.build.date=Wed May  7 04:29:20 EDT 2014
FFOS_Phone: Inari on v1.4
Remote Phone: GT-I9100

Since I'm not able to reproduce the issue on my test environment, I would like to need info the reporter for more message as following.

* Remote device
* Any other steps you did on the remote phone
* Reproduced rate

Thanks for your information.

Comment 6

[Kai-Chih Hu [:khu]]

Ian, so, is there any useful information from the logcat? Does the eror mean anything? 

04-29 10:49:24.246   286   286 I GeckoBluetooth: OnSocketDisconnect: [server]
04-29 10:49:24.246   286   286 I GeckoBluetooth: OnSocketDisconnect: [server]
04-29 10:49:24.266   286   286 E Sensors : sensors_poll_context_t->activate(handle: 0, enabled: 1)
04-29 10:49:24.266   286   286 D Sensors : AccSensor::enable(en=1) : fd=272, path=/sys/class/input/event0/device/device/enable_device
04-29 10:49:24.346   286   286 I GeckoBluetooth: OnSocketConnectError: [client]
04-29 10:49:24.356   286   286 I GeckoBluetooth: DiscardBlobsToSend: idx 0
04-29 10:49:24.366   286   286 I GeckoBluetooth: ProcessNextBatch: REMOVE. 0 remaining

Is it the reason to send out the error message? 
I checked another log, and found a process named "Send To Bluetoo" was active from 20140429_10:49:01 to 20140429_10:49:25: 

----------------20140429_10:49:01-------------------
                          |     megabytes     |
           NAME  PID PPID CPU(s) NICE  USS  PSS  RSS VSIZE OOM_ADJ USER    
            b2g  286    1   21.6    0 60.9 66.6 79.4 199.8       0 root    
         (Nuwa)  834  286    1.2    0  2.7  8.0 20.5  51.0       0 root    
     Homescreen  895  834    2.4   18 10.2 14.2 26.0  68.2       8 u0_a895 
        Gallery 1130  834    2.4    1 26.7 30.8 42.9  92.4       2 u0_a1130
Send To Bluetoo 1341  834    0.6    1  6.4  9.9 20.7  63.3       2 u0_a1341

----------------20140429_10:49:25-------------------
                          |     megabytes     |
           NAME  PID PPID CPU(s) NICE  USS  PSS  RSS VSIZE OOM_ADJ USER    
            b2g  286    1   24.6    0 58.1 63.1 76.9 210.3       0 root    
         (Nuwa)  834  286    1.3    0  2.4  7.2 20.5  51.0       0 root    
     Homescreen  895  834    2.5   18 10.0 12.8 26.0  67.2       8 u0_a895 
        Gallery 1130  834    3.3    1 26.0 28.9 42.3  92.3       2 u0_a1130
Send To Bluetoo 1341  834    3.2    1  8.3 10.7 23.5  70.0       2 u0_a1341
       Settings 1389  834    2.6    1 16.5 19.0 32.1  79.1       2 u0_a1389
(Preallocated a 1530  834    0.5   18  4.5  7.1 18.2  58.1      10 u0_a1530

But as you can see, the log file collected logs from 20140429_10:48:50 to 20140429_10:50:04. Well, I can't recognize if it meant that the Bluetooth transfer was completed successfully or not from the log. 

The timing that error was happened is very closed to the timing that the last "Send To Bluetoo" log from the process list. I am not sure if they're related. Not sure if Eric has other insight on this?

Comment 7

[[e-mail], [e-mail]]

I cannot identify the file was sent or not in Gecko side via above log(adb shell b2g-info). Since I don't see the progress in the utility tray, I guess Gaia might not be received "bluetooth-opp-transfer-start" event. It might mean that the file was requested to send. Then, the request was failed before the file was sending in byte-sit. This speculation may be wrong. We should see the error code for verification. It will need Gecko devs for investigation.

Comment 8

[Lionel Mauritson]

Device: Flame 1.4F MOZ
BuildID: 20140508000201
Gaia: 4ce973ef0732b0d52cb043210db598aa176b2ce9
Gecko: 16ab7f6b18f8
Version: 30.0
Firmware Version: v10E

On remote device I enabled Bluetooth and Visible to all.
I accepted the pair request.
Sometimes the file is not successfully sent, though the message "The transfer has started" appears AFTER the error message on the initiating device. Sometimes the file is sent even though there is an error message.

Sometimes the "Unable to pair" message is the fullscreen version (On the initiating device) instead of the notification bar version. In this case the file usually sends.

Roughly 75% of the time some sort of issue occurs.

Comment 9

[howie [:howie]]

Hi Ben, could you help to take a look? Thanks.

Comment 10

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

It looks like SDP records had been fully updated, still need to dig into why this happens on flame.

Comment 11

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

Change assignee.
Shawn is working on Bug 1005901.

Comment 12

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

Attachment: If user try to send a file to a device which just completes the pairing process, the OPP manager may update SDP records when it's not ready. (v0)

Comment 13

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

Comment on attachment 8422376 [details] [diff] [review]
If user try to send a file to a device which just completes the pairing process, the OPP manager may update SDP records when it's not ready. (v0)

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

Having the 2nd SDP query for me is fine, but I think query earlier could be better. And please correct commit message, "If user 'tries'"

::: dom/bluetooth/bluez/BluetoothOppManager.cpp
@@ +40,1 @@
>  

Alphabetical order?

@@ +1556,4 @@
>        bs->UpdateSdpRecords(aDeviceAddress, this);
>      } else {
> +      TimeDuration duration = TimeStamp::Now() - mLastServiceChannelCheck;
> +      // Refresh SDP records until it get valid service channel

until it gets a valid service channel

@@ +1558,5 @@
> +      TimeDuration duration = TimeStamp::Now() - mLastServiceChannelCheck;
> +      // Refresh SDP records until it get valid service channel
> +      // unless timeout is hit.
> +      if (duration.ToMilliseconds() < kSdpUpdatingTimeoutMs) {
> +        bs->UpdateSdpRecords(aDeviceAddress, this);

This gives us the 2nd shoot, but I wonder why the 1st SDP query failed during inline pairing completed. Maybe we can query SDP records after CreateDevice. 
See http://androidxref.com/4.0.4/xref/frameworks/base/core/java/android/server/BluetoothEventLoop.java#890

Then we don't need to fetch the service channel first and query SDP again.

Comment 14

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

Attachment: If user try to send a file to a device which just completes the pairing process, the OPP manager may update SDP records when it's not ready. (v1)

Hi Shawn,

Thank you for your comments.
A few minor changes was made on #[patch 2].

I try to listen to the DBus signal "DeviceCreated" and check the timing of DBus method_call "CreatePairedDevice", however, they could happen before service discovery complete.

The service channel would be valid after search_completed_cb() or create_device_reply() has been called in Bluez, but I can't found a proper way to notice gecko that SDP records are ready through DBus. If gecko wants to observe the progress of SDP updating, we have to add a new DBusSignal to GDBusSignalTable in Bluez, which would change the interface.

On the other hand, make SDP query happen earlier did help to avoid to get invalid service channel in some cases. However, no matter how early SDP updating get started, it can't guarantee the service channel is ready for OBJECT_PUSH. Especially for inline pairing, the SDP query is triggered right after device get paired.

Since gecko wouldn't get the notice when SDP records is ready, In the #[patch 2], OppManager would try to get valid service channel until the timeout is hit.

Comment 15

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

Hi Shawn,

Thank you for your comments.
A few minor changes was made on Attachment #8423065 [details] [diff].

I try to listen to the DBus signal "DeviceCreated" and check the timing of DBus method_call "CreatePairedDevice", however, they could happen before service discovery complete.

The service channel would be valid after search_completed_cb() or create_device_reply() has been called in Bluez, but I can't found a proper way to notice gecko that SDP records are ready through DBus. If gecko wants to observe the progress of SDP updating, we have to add a new DBusSignal to GDBusSignalTable in Bluez, which would change the interface.

On the other hand, make SDP query happen earlier did help to avoid to get invalid service channel in some cases. However, no matter how early SDP updating get started, it can't guarantee the service channel is ready for OBJECT_PUSH. Especially for inline pairing, the SDP query is triggered right after device get paired.

Since gecko wouldn't get the notice when SDP records is ready, in the Attachment #8423065 [details] [diff], OppManager would try to get valid service channel until the timeout is hit.

Comment 16

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

Comment on attachment 8423065 [details] [diff] [review]
If user try to send a file to a device which just completes the pairing process, the OPP manager may update SDP records when it's not ready. (v1)

LGTM. We have tried various ways to do SDP query earlier after pairing completed. But it seems there is no guarantee we can get SDP query completed at that critical timing. So we probably have to query a few times.

Comment 17

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

(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #16)
> Comment on attachment 8423065 [details] [diff] [review]
Shawn,
Thank you for your review.

It's been put on the try server.
https://tbpl.mozilla.org/?tree=Try&rev=a2127916e312

Comment 18

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

Attachment: (for master) (for 1.4) If user tries to send a file to a device which just completes the pairing process, the OPP manager may update SDP records when it's not ready. (v1) r=shuang

It looks fine on try server.
https://tbpl.mozilla.org/?tree=Try&rev=a2127916e312

Comment 19

[Ben Tian (inactive)]

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

Comment 20

[Lionel Mauritson]

I am unable to obtain a regression window as this issue reproduces on the earliest central flame build available.

Device: Open_C
BuildID: 20140417000006
Gaia: 7591e9dc782ac2e97d63a96f9deb71c7b3588328
Gecko: e71ed4135461
Version: 31.0a1
Firmware Version: P821A10V1.0.0B06_LOG_DL

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/d88efe4f0ca4

Comment 22

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/224d4344dabf

Comment 23

[Yeojin Chung [:YeojinC]]

The error was still reproduced at about 10% frequency on v1.4 (Buri & Flame). The following devices were tested:

1.4F Environmental Variables:
Device: Flame 1.4F
BuildID: 20140522000200
Gaia: 233dd43b3b976e66a619dbc1b4044ed1e3ca3e34
Gecko: c3c0c57daef8
Version: 30.0
Firmware Version: v10F-3

-----------------------------------------------------

1.4 Environmental Variables:
Device: Buri 1.4 MOZ
BuildID: 20140522000200
Gaia: 233dd43b3b976e66a619dbc1b4044ed1e3ca3e34
Gecko: c3c0c57daef8
Version: 30.0
Firmware Version: v1.2-device.cfg

-----------------------------------------------------

1.4 Environmental Variables:
Device: Open_C 1.4
BuildID: 20140522000200
Gaia: 233dd43b3b976e66a619dbc1b4044ed1e3ca3e34
Gecko: c3c0c57daef8
Version: 30.0
Firmware Version: v10F-3


----------------------------------------------------

2.0 Environmental Variables:
Device: Open_C 2.0
BuildID: 20140522040230
Gaia: ef66efa34ed8a559c8998bde688fae88eb943a7a
Gecko: b40296602083
Version: 32.0a1
Firmware Version: P821A10V1.0.0B06_LOG_DL

Comment 24

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

(In reply to ychung from comment #23)
> The error was still reproduced at about 10% frequency on v1.4 (Buri &
> Flame). The following devices were tested:

Thank you for reporting this issue.
I can't reproduced this bug on Buri by following the STR which Lionel posted on #Description.
P.S. Since the frequency is about 10%, I would keep trying.

May I ask few questions about the steps to reproduce ?

1. Did you unpair both devices for each your tests?
   or did you keep them paired on both devices?
2. Did the error message "File could not be sent" appeared before "The transfer has started" appeared ?
   or it appeared after "The transfer has started" ?

It is a similar known issue that our devices can't send files to a paired devices which has delete its link key. The OS X didn't handle this case neither. 
This issue would be tracked on Bug 1015083 and mozilla plan to solve it recently.

Thank you.

Comment 25

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

(In reply to Jamin Liu [:jaliu] from comment #24)
> (In reply to ychung from comment #23)
> > The error was still reproduced at about 10% frequency on v1.4 (Buri &
> > Flame). The following devices were tested:
> 
> Thank you for reporting this issue.
> I can't reproduced this bug on Buri by following the STR which Lionel posted
> on #Description.
> P.S. Since the frequency is about 10%, I would keep trying.
> 
> May I ask few questions about the steps to reproduce ?
> 
> 1. Did you unpair both devices for each your tests?
>    or did you keep them paired on both devices?
> 2. Did the error message "File could not be sent" appeared before "The
> transfer has started" appeared ?
>    or it appeared after "The transfer has started" ?

Just one more question.
Thank you very much.

3. Could the file be sent successfully when you reproduced this bug ?

Comment 26

[Yeojin Chung [:YeojinC]]

(In reply to Jamin Liu [:jaliu] from comment #25)
> (In reply to Jamin Liu [:jaliu] from comment #24)
> > (In reply to ychung from comment #23)
> > > The error was still reproduced at about 10% frequency on v1.4 (Buri &
> > > Flame). The following devices were tested:
> > 
> > Thank you for reporting this issue.
> > I can't reproduced this bug on Buri by following the STR which Lionel posted
> > on #Description.
> > P.S. Since the frequency is about 10%, I would keep trying.
> > 
> > May I ask few questions about the steps to reproduce ?
> > 
> > 1. Did you unpair both devices for each your tests?
> >    or did you keep them paired on both devices?
> > 2. Did the error message "File could not be sent" appeared before "The
> > transfer has started" appeared ?
> >    or it appeared after "The transfer has started" ?
> 
> Just one more question.
> Thank you very much.
> 
> 3. Could the file be sent successfully when you reproduced this bug ?

1. I did unpair devices and re-pair each time before I tried transferring. 
2. The only error message I observed was the pairing failure message, even after the pairing was successful. Those two messages you mentioned did not appear.
3. Yes. The file transfer was successful 100%.

I've only got the error message 1 time on Buri, and 1 time on Flame when I tried multiple times. I only reported this issue because it DID occur on 2 different devices, although at a very low rate.

I hope this was helpful. Please let me know if you need more information. Thanks!

Comment 27

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

Thank you, ychung. It does help.

It seems like there are two issues was described in this bug.

The first issue is that the error message "File could not be sent" may appear even we sent file successfully. This issue has 75% reproducing frequency and the video of this issue was posted at #Descrition. ( http://youtu.be/wbrLUCIqgBY )

The second issue is that the error message "Unable to pair devices" may appear even we sent file successfully. This issue has lower reproducing frequency.(10%)
Ychung reported it still occur after Attachment #8423065 [details] [diff] landed.
( Lionel mentioned this issue in #comment 8. )

I'll trace investigate the second issue tomorrow .
If it's not relative to Bug 1015083, I'll create a new bug or reopen this bug to trace it.

Comment 28

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

Hi ychung,
May I ask what kind of remote device you used in your test?
If you use another FxOS phone as a remote device, could you tell me the device info. in brief ? 
(ex: 1.4 Flame)

Thanks for your information.

Comment 29

[Yeojin Chung [:YeojinC]]

I used 1.4 Buri, 1.4 Open C, 1.4 Flame, and 2.0 Open C. I paired these devices in different combinations.