1114479 - [FFOS2.0][Woodduck][BT]cannot send file to a unpaired remote device via BT

Status: RESOLVED WORKSFORME

(Firefox OS Graveyard :: Gaia::Bluetooth, defect, P2)

Description

[sync-1]

Created an attachment (id=1023892)
 log
 
 PR Reporter:欧阳文丽
  contact:0752-2639312(61312)
 		
  DEFECT DESCRIPTION:
 >Cannot send file to unpaired remote device via BT.
 
  REPRODUCING PROCEDURES:
 1.open BT in MS and remote device;
 
 2.send a file to remote device via BT;
 
 3.it will pop-up pair message, click to pair;
 
 4.pop-up"file could not send" in MS--KO1;
 
 5.send a file to remote device via BT again, still pop-up"file could not send"--KO2.
 PS:The issue can't stable reproduced.
  EXPECTED BEHAVIOUR:
 >Can send file normally via BT.
 
  ASSOCIATE SPECIFICATION:
 
  TEST PLAN REFERENCE:
 
  TOOLS AND PLATFORMS USED:
 
  USER IMPACT:
 
  REPRODUCING RATE:
 
  For FT PR, Please list reference mobile's behavior:

Comment 1

[sync-1]

Attachment: log

Comment 2

[sync-1]

Hi mozilla coleague,
 
 It's unstable issue,it can not send file to unpaired remote device sometime.From log,I can see some timeout closing channel lead to issue,but our validation say that it very fast to pop-up "file could not send",so please help to analyse it.Thanks!
 
 11-14 11:47:27.475   177   177 D BTSNIFF : ucTemp[16~23]=0, 225, 229, 131, 64, 158, 17, 192
 11-14 11:47:27.475   177   177 D [BT]    : mtk_bt_read: buffer 402ada7c, len 1
 11-14 11:47:27.479   971   971 I Gecko   : 
 11-14 11:47:27.479   971   971 I Gecko   : ###!!! [Child][MessageChannel] Error: Channel closing: too late to send/recv, messages will be lost
 11-14 11:47:27.479   971   971 I Gecko   : 
 11-14 11:47:27.480   177   177 D [BT]    : mtk_bt_read: buffer 402ada7c, len 1

Comment 3

[Josh Cheng [:josh]]

HI Shawn,
Is this dup bug 1111907?
Thanks!

Comment 4

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

(In reply to Josh Cheng [:josh] from comment #3)
> HI Shawn,
> Is this dup bug 1111907?
> Thanks!

No. They are not the same problem.

Comment 5

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

I will check this bug first, thanks.

Comment 6

[zhensen.su]

Hi Shawn,

Can you saw something wrong from log?

Comment 7

[zhensen.su]

Hi Shawn,

How about the issue?

Comment 8

[Josh Cheng [:josh]]

Hi Norry,
qawanted for Woodduck 2.0M and Flame 2.0/2.1/2.2. Thanks!

Comment 9

[zhensen.su]

Hi Josh,

The issue is difficult to reproduce,so i think you could see the log,I can see something wrong about timeout,then close channel,but validation say that it's fast pop-up "file could not send".I don't know why couse it.Please help check it.

Comment 10

[Josh Cheng [:josh]]

Hi Reporter,
We cannot repo this issue on our side. Can you try repo the issue with Mozilla Gaia/Gecko? Thanks!

User build image link is: http://pan.baidu.com/s/1hqnDBtM
Access code: 9c9u
unzip password: erT14moz

Comment 11

[sync-1]

(In reply to comment #9)
 > Comment from Mozilla:Hi Reporter,
 > We cannot repo this issue on our side. Can you try repo the issue with Mozilla
 > Gaia/Gecko? Thanks!
 > User build image link is: http://pan.baidu.com/s/1hqnDBtM
 > Access code: 9c9u
 > unzip password: erT14moz
 Hi Josh,
 
 It's also difficult reproduce in our side,so i will try my best to repro it.
 In addition,you can see the log we support for analyze.
 
 Thanks!

Comment 12

[Ben Tian (inactive)]

Based on comment 1 log file, bluetooth socket is disconnected from stack for some reason, so 'File could not be sent' pops accordingly. I'll try to reproduce on my device for more info.

zhensen, can you help check why stack disconnects bluetooth socket?

reporter, what is the reproducing rate?

==
11-14 11:47:46.934   167   709 I         : [JSR82][JBT] JBT bt_handle_session_disconnect_ind parms.ps_type:01
11-14 11:47:46.934   167   709 I         : [JSR82][JBT] JBT: jbt_reset_session_entry()
11-14 11:47:46.934   167   709 I         : [JSR82][JBT] JBT UT: Deregister service success: release rw ring buffer
11-14 11:47:46.934   167   709 I MTKBT   : [Session]session_destroy: name [bt.session.default], id[28], subid[167]
11-14 11:47:46.934   167   709 I BTIF_CORE: out profile[13] handler!
11-14 11:47:46.934   167   709 I BTIF_CORE: [btif_task]:Start polling!
11-14 11:47:46.938   177   177 I MTKBT   : [Session]session_destroy: name [bt.session.default], id[28], subid[167]
...
11-14 11:47:46.939   167   167 I GeckoBluetooth: OnSocketDisconnect: [client]

Comment 13

[zhensen.su]

Hi Ben,

It reproduce about 1/3,could tell me how to get more information about socket?I can't anlyze anything except the paste error.

Comment 14

[Ben Tian (inactive)]

Zhensen,

Gecko bluetooth transfers files via bluetooth socket. When a device (sender) wants to send files to another device (receiver), sender would request bluetooth socket's file descriptor (fd) from bluetooth stack to connect to receiver. After bluetooth socket is connected, sender communicates with and transfers data to receiver via bluetooth socket [1][2]. Bluetooth socket would be closed if error or no data is read on socket fd [3]. Therefore we should check why stack reports error/no data on socket fd.

[1] http://hg.mozilla.org/releases/mozilla-b2g32_v2_0m/file/9804735ff433/dom/bluetooth/bluedroid/BluetoothSocket.cpp#l570
[2] http://hg.mozilla.org/releases/mozilla-b2g32_v2_0m/file/9804735ff433/dom/bluetooth/bluedroid/BluetoothSocket.cpp#l636
[3] http://hg.mozilla.org/releases/mozilla-b2g32_v2_0m/file/9804735ff433/dom/bluetooth/bluedroid/BluetoothSocket.cpp#l575

==
Gecko bluetooth log meanings:

11-14 11:47:26.956   167   167 I GeckoBluetooth: ReceiveSocketInfo: size 16 channel 23 remote addr 29:2d:f1:9f:5c:74 status 0
11-14 11:47:26.956   167   167 I GeckoBluetooth: OnSocketConnectSuccess: [client]
>>> bluetooth socket is connected.

11-14 11:47:46.939   167   167 I GeckoBluetooth: OnSocketDisconnect: [client]
>>> bluetooth socket is disconnected.

Comment 15

[Ben Tian (inactive)]

Zhensen,

Also after the bug occurs, do all later transfers fail as well? Or they are unaffected by this bug failure?

Comment 16

[zhensen.su]

(In reply to comment #14)
> Comment from Mozilla:Zhensen,
> Also after the bug occurs, do all later transfers fail as well? Or they are
> unaffected by this bug failure?

Hi ben,

do all later transfers fail as well?---yep.But if turn off/on BT,it can be
transfer success.

Comment 17

[Norry.L.F(Leave from Mozilla)]

I can't repro this bug on Flame 2.0/2.1/2.2. And I will keep tracking it to repro.

Rate:0/20

Flame 2.0 build:
Gaia-Rev        3c9bb36d9ade1a0acd5e1d6cbb5057be7f5ad484
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/93f5c85a1d31
Build-ID        20150103000200
Version         32.0
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.cltbld.20150103.034538
FW-Date         Sat Jan  3 03:45:49 EST 2015
Bootloader      L1TC000118D0
---------------------
Flame 2.1:
Gaia-Rev        73be51f998031f06db0cd660c0e388fa621c9f4c
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/05dd053f1d90
Build-ID        20150103001211
Version         34.0
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.cltbld.20150103.034952
FW-Date         Sat Jan  3 03:50:03 EST 2015
Bootloader      L1TC000118D0
---------------------
Flame 2.2:
Gaia-Rev        698e6e8a098cc060b26cd6f25171633c4c7e739d
Gecko-Rev       https://hg.mozilla.org/mozilla-central/rev/57e4e9c33bef
Build-ID        20150103010205
Version         37.0a1
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.cltbld.20150103.045144
FW-Date         Sat Jan  3 04:51:56 EST 2015
Bootloader      L1TC000118D0

Comment 18

[Ben Tian (inactive)]

Hi Josh, Zhensen was answering me, not asking question.

(In reply to zhensen.su from comment #16)
> Hi ben,
> 
> do all later transfers fail as well?---yep.But if turn off/on BT,it can be
> transfer success.

Comment 19

[zhensen.su]

Hi ben,

Do you have any result from log?

Comment 20

[Ben Tian (inactive)]

Please refer to comment 12 for my finding on current log.

(In reply to zhensen.su from comment #19)
> Hi ben,
> 
> Do you have any result from log?

Comment 21

[woodduck]

From attach BT stack log, there are two times OPP transfer procedure.
(1)1th time: 
11:47:26.xxx, OPP start connection success;
11:47:46.xxx, OPP canceled by remote, receive remote RFCOMM DISC command.

(2)2th tume:
11:47:55.xxx, OPP start connection success;  
11:48:17.xxx, OPP canceled by remote, receive remote RFCOMM DISC command.

Both ~20s canceld by remote, i think need more test with this device(BT ADDR:29,2d,f1,9f,5c,74).
Local can't reproduce with other device.

Comment 22

[Ben Tian (inactive)]

(In reply to woodduck from comment #21)
> From attach BT stack log, there are two times OPP transfer procedure.
> (1)1th time: 
> 11:47:26.xxx, OPP start connection success;
> 11:47:46.xxx, OPP canceled by remote, receive remote RFCOMM DISC command.
> 
> (2)2th tume:
> 11:47:55.xxx, OPP start connection success;  
> 11:48:17.xxx, OPP canceled by remote, receive remote RFCOMM DISC command.
> 
> Both ~20s canceld by remote, i think need more test with this device(BT
> ADDR:29,2d,f1,9f,5c,74).
> Local can't reproduce with other device.

sync-1,

Please also provide remote device info to help reproduce/clarify.

Comment 23

[zhensen.su]

Hi ben,

The remote device use android MS and it is difficult to repro,but it break out many times when first time to attempt send file to a unpaired remote device via BT.

Comment 24

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

If OPP cancelled connection by the remote, can you see any reason why the remote is trying to reject RFCOMM connection?

Comment 25

[Ben Tian (inactive)]

Attachment: wd-opp.patch

Zhensen,

Please help reproduce with attached patch that shows more bluetooth transfer log. If you meet the bug with FxOS receiver, attach receiver logs as well.

Comment 26

[zhensen.su]

Hi Ben,

I will try repro it use your patch and catch both sides log.

Thanks!

Comment 27

[Josh Cheng [:josh]]

Hi Zhensen,
any update? Thanks!

Comment 28

[zhensen.su]

Hi Josh,

VAL has reproduced the issue,but forget open mtklog.We have tried to reproduced again and get log,please wait it.

Thanks!

Comment 29

[Josh Cheng [:josh]]

Wait until partner provide new log.

Comment 30

[zhensen.su]

Hi Josh,

VAL had not reproduced the issue now,I have submit the 'attachment 8546537 [details] [diff] [review]',you can resolved it.If we reproduce the issue,i will inform you to activate.

Thanks!

Comment 31

[Josh Cheng [:josh]]

Hi Zhensen,
We will close the issue for now. Please reopen if VAL can repo this issue and attach new log. Thanks!

Comment 32

[zhensen.su]

Attachment: mtklog.rar

Hi Josh,

The issue has reproduced by val,the log is in attachment,please check it.

Thanks!

Comment 33

[zhensen.su]

Hi Josh,

The reproduce time at 14：21.

Thanks!

Comment 34

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

Hi Will,
Please help to check the latest log.

Comment 35

[Josh Cheng [:josh]]

Hi Will,
Could you please help to check the new log per comment 32? Thanks!

Comment 36

[Ben Tian (inactive)]

Zhensen, the logs show bluetooth socket is closed for no data is read (ret == 0) on socket fd [1]. We need chipset partner to check why socket fd returns no data in bluetooth stack.

Also are these logs from sender or receiver? Do you have logs from the other side?

[1] http://hg.mozilla.org/releases/mozilla-b2g32_v2_0m/file/9804735ff433/dom/bluetooth/bluedroid/BluetoothSocket.cpp#l575

==
02-13 14:21:25.282   165   431 I GeckoBluetooth: OnFileCanReadWithoutBlocking: fd 261 ret 0 errno b
02-13 14:21:25.282   165   431 I GeckoBluetooth: OnFileCanReadWithoutBlocking: close socket

(In reply to zhensen.su from comment #32)
> Created attachment 8563934 [details]
> mtklog.rar
> 
> Hi Josh,
> 
> The issue has reproduced by val,the log is in attachment,please check it.
> 
> Thanks!

Comment 37

[zhensen.su]

Hi Ben,

It's sender's log,we don't get receiver's log,Could you help to ask Corresponding chipset engineer to see it?

Comment 38

[Josh Cheng [:josh]]

Hi Jason,
Could you please help to check this issue? Thanks!

Comment 39

[woodduck]

Hi Dexiang, Please check it. Thanks.

Comment 40

[[e-mail]]

Hi Dexiang, 

    any progress of this issue?

Comment 41

[dexiang jiang]

Dear Zhensen/Jiabin,
The latest reproduce log shows opp failed caused by remote device didn't response l2cap conenction request(sdp flow) in 10s, it should be remote IOT issue.
There are three times OPP share procedure, after ACL created/paired, OPP will start SDP to query channel info, but remote device alwasys no response after host send l2cap request, then 10s timeout happend and renturn OPP failed.
From experience, its remote device IOT issue, the test device named "HPIXI3(45)", so remote device is PC + BT dongle? Refer phone can send OPP succussfully?

Thanks.

Comment 42

[[e-mail]]

(In reply to dexiang jiang from comment #41)
> Dear Zhensen/Jiabin,
> The latest reproduce log shows opp failed caused by remote device didn't
> response l2cap conenction request(sdp flow) in 10s, it should be remote IOT
> issue.
> There are three times OPP share procedure, after ACL created/paired, OPP
> will start SDP to query channel info, but remote device alwasys no response
> after host send l2cap request, then 10s timeout happend and renturn OPP
> failed.
> From experience, its remote device IOT issue, the test device named
> "HPIXI3(45)", so remote device is PC + BT dongle? Refer phone can send OPP
> succussfully?
> 
> Thanks.

we has used several different phone as remote device to test this issue.and when this happened,all the remote device works normally with other device.And MS doesn't wait 10s,it report error very quick.So we think that it's not remote device's problem.

Comment 43

[dexiang jiang]

Hi Jiabin,

1. Could you help to share remote device info?
   > what's the remote device?
   > reproduce rate? 
   > each remote has same reproduce rate or not?
   > if possibal to get remote log(main log, bt virtual sniffer log)?
   > if possibal tp get air log(ellysis log, air sniffer log)?
2. "And MS doesn't wait 10s,it report error very quick"
   from log, three times failed both are 10s timeout, its impossible resopnse error quickly.
   please help to confirm it.

Thanks a lot.

Comment 44

[[e-mail]]

(In reply to dexiang jiang from comment #43)
> Hi Jiabin,
> 
> 1. Could you help to share remote device info?
>    > what's the remote device?
       android phone PIXI3-4，PIXI3-3.5，PIXI3-4.5 of TCL
>    > reproduce rate? 
       all this phone has reproduced once, it's difficult to reproduce
>    > each remote has same reproduce rate or not?
       not enough data to calculate the rate, it looks like nearly.
>    > if possibal to get remote log(main log, bt virtual sniffer log)?
>    > if possibal tp get air log(ellysis log, air sniffer log)?
       we are trying to get the remote mtklog, but it's difficult to reproduce.
> 2. "And MS doesn't wait 10s,it report error very quick"
>    from log, three times failed both are 10s timeout, its impossible
> resopnse error quickly.
     validation say that it's fast pop-up "file could not send".I don't know why couse it.Please help check it.--from comment#9
>    please help to confirm it.
> 
> Thanks a lot.

Comment 45

[[e-mail]]

hi dexiang,

base on comment#18:
after the bug occurs, do all later transfers fail as well.
But if turn off/on BT,it can be transfer success.

Comment 46

[dexiang jiang]

Dear Jiabin,
Turn off/on BT on send side or remote side?

Comment 47

[[e-mail]]

(In reply to dexiang jiang from comment #46)
> Dear Jiabin,
> Turn off/on BT on send side or remote side?

on send side.

Comment 48

[dexiang jiang]

Dear Jiabin,
Please help to try to get remote log and air log, thanks a lot.
Also i will ask our BT controller/l2cap owner to comment possible root causes.

Comment 49

[Peipei Cheng (needinfo if you need my action)]

jiabin, could you please help with comment 48?

Comment 50

[[e-mail]]

dear all,

    postpone this issue, until we can reproduce it and catch both side log.