1043856 - [NFC] When receiver's BT on, receiver sometimes would get file transfer request dialog while NFC transfer file

Status: VERIFIED FIXED

(Firefox OS Graveyard :: NFC, defect)

Description

[Alison Shiue]

Attachment: nfc_query_dialog.mp4

Gaia      c72257b2d27135bfcd68e89dd584182797784016
Gecko     https://hg.mozilla.org/mozilla-central/rev/616e6924cb0b
BuildID   20140724160202
Version   34.0a1

STR:
Tap 2 phones to share an image

Expected result:
Share successfully

Actual result:
Files cannot be shared easily, sometimes, when receiver's BT initial turn on, receiver would get file transfer request dialog.

Comment 1

[Alison Shiue]

Attachment: receiver_hcidump.log

Comment 2

[Alison Shiue]

Attachment: sender_logcat.log

Comment 3

[Alison Shiue]

Attachment: receiver_logcat.log

Comment 4

[Alison Shiue]

[Blocking Requested - why for this release]:

Comment 5

[Vincent Chang[:vchang][changyihsin]]

Hi arno, do you mind to take a look at this bug?

Comment 6

[arno]

Alison: I took a look at the video. Can you verify that the receiver first showed a notification that the transfer failed and then showed the file transfer dialog? I think I saw it in the video but wanted to double check with you. What is happening is that the receiver times out the transfer request (the timeout is currently 6 seconds). At that point the receiver cancels the file transfer and if the sender then sends the file, the BT transfer app will show the dialog. If that is what is happening, the solution is to increase the timeout that cancels the handover request. I only have one Flame device and I've used an Android device as the second device. The 6 second timeout seemed to be ok in that configuration.

Comment 7

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

(In reply to arno from comment #6)
> Alison: I took a look at the video. Can you verify that the receiver first
> showed a notification that the transfer failed and then showed the file
> transfer dialog? 
Yes

> the BT
> transfer app will show the dialog. 
BT trasnfer dialog shouldn't be shown.

Comment 8

[arno]

Attachment: Timeout patch

The receive file dialog is shown because NfcHandoverManager timed out the handshake. I've attached a mini-patch that increases the timeout to 8 seconds. Should I request a review or can you flash a version for Alison to test? Again, I only have one Flame device so I cannot do that test myself.

Comment 9

[Alison Shiue]

[Blocking Requested - why for this release]:

2.0 also can reproduce this issue. Please fix on both code branches.

Gaia  	0a864988f5dce7f9f3dea9609e8ef054679c30ff
Gecko 	https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/2da96d621030
BuildID   20140727160207
Version   32.0

Comment 10

[arno]

(In reply to ashiue from comment #9)
> [Blocking Requested - why for this release]:
> 
> 2.0 also can reproduce this issue. Please fix on both code branches.

Since the 2.0 branch uses the same timeout, this is to be expected.

Comment 11

[arno]

Attachment: Increase handover timeout

Comment 12

[howie [:howie]]

Triage: 2.0+

Comment 13

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

Comment on attachment 8463296 [details] [review]
Increase handover timeout

if this fixes what the real problem..

Comment 14

[arno]

(In reply to Alive Kuo [:alive][NEEDINFO!] from comment #13)
> Comment on attachment 8463296 [details] [review]
> Increase handover timeout
> 
> if this fixes what the real problem..

Can't tell is that is supposed to be a question or a comment. The NFC and BT protocols do not share any state information. In certain circumstances race conditions are unavoidable. E.g., when the BT Transfer App receives an incoming file transfer request, it cannot be determined with 100% certainty if that request originated from a NFC handover or not. The timeout can only reduce the likelihood of a race condition but cannot avoid it.

Comment 15

[Ryan VanderMeulen [:RyanVM]]

Master: https://github.com/mozilla-b2g/gaia/commit/6a3e55ac1391a78ee77f247d69bb3f71da43ece9

Comment 16

[Ryan VanderMeulen [:RyanVM]]

v2.0: https://github.com/mozilla-b2g/gaia/commit/9369f7f9a4795d7d554c6c1ddb3c7daee3e4f994

Comment 17

[Alison Shiue]

I tried file transfer many times on 
Gaia      b67ddd7d40b52e65199478b8d6631c2c28fdf41d
Gecko     https://hg.mozilla.org/mozilla-central/rev/005424a764da
BuildID   20140730160200
Version   34.0a1

Here are the test result:
[Both phones BT on - Total 35 times]
Pass - 25
Fail - 10 (5 show BT transfer request dialog)

[Both phones BT off - Total 35 times]
Pass - 33
Fail - 2 (0 show BT transfer request dialog)

I think the fail rate still high when BT initial on on both test devices, and the transfer request issue could hit 5 times. 
Hi Arno, since I could not (until now) hit transfer request dialog issue when BT initial off on both test devices, is timeout the only root cause?  My question is why BT initial off do not have the higher probability to hit this problem?

Comment 18

[Vincent Chang[:vchang][changyihsin]]

Hi Alison, thanks for your hard working on verifying this bug. Based on your test result, I think we should reopen this bug. 

Hi arno, do you think you can provide a better solution to fix the problem. Looks like extending the timeout doesn't fix the problem.

Comment 19

[Vincent Chang[:vchang][changyihsin]]

Hi Ryan, can you help to backout the gaia patch?

Comment 20

[Ryan VanderMeulen [:RyanVM]]

Master: https://github.com/mozilla-b2g/gaia/commit/8377465fb15ff32eb69e46332d73644334109a6c
v2.0:   https://github.com/mozilla-b2g/gaia/commit/96e9dd793fe5aeea5a144b93f7f448f2fbe95f6d

Comment 21

[arno]

(In reply to ashiue from comment #17)
> I think the fail rate still high when BT initial on on both test devices,
> and the transfer request issue could hit 5 times. 
> Hi Arno, since I could not (until now) hit transfer request dialog issue
> when BT initial off on both test devices, is timeout the only root cause? 
> My question is why BT initial off do not have the higher probability to hit
> this problem?

Alison: first of all thank you for the hard work on testing this patch.

Shawn: I only have one Flame device and cannot reproduce Alison's setup. However, I just tried sending a file from Android to Flame via a NFC handover. The Android device is the sender and the Flame device is the receiver (BT enabled on both devices). I managed to send 26 times without any flaw. After that the file transfers consistently failed. The interesting thing is that the Android devices pops open a message saying "Receiver's device does not support large file transfer via beam." Does this tell you something?

Comment 22

[arno]

Shawn: I canceled the ni because I dug into the logs and found another problem that is unrelated to BT.

Dimi: I am sending files from Android to Flame via a handover. After several successful transfers, nfcd does not send the Handover Select message back to Android anymore. I've attached two logs that show a working and a non-working example. Do a grep on NFC:WriteNDEF in the logs. That is where NfcHandoverManager sends the Handover Select NDEF message back to the peer. In the working log you can see that nfcd receives the message and then actually performs the sending of the Hs record. The non-working log shows that nfcd receives the message but for some reason then stops processing it.

STR:
- Device 1: Android (Nexus 5, 4.4.4)
- Device 2: Flame
  Gaia: https://github.com/svic/gaia/tree/Bug_1043856
  Gecko: 46c9b0371c8c4591e0e8bd5e889a8555e5e1e4ce
  nfcd: b6f025acd8ead1c3531e1ad62e70849161ed9340

- Enable BT on both devices
- Send a picture from Android to Flame via beam
- Repeat sending until error occurs (happened for me from somewhere 6-26 attempts)

Comment 23

[arno]

Attachment: Log showing a successful sending of an Hs record

Comment 24

[arno]

Attachment: Log showing an unsuccessful attempt to send an Hs record

Comment 25

[Dimi Lee [ooo 16.04 - 21.04］]

Attachment: nfcd

Hi Arno,
 From the log I cannot get enough information to know what exactly the problem is.
And I update the latest gecko/gaia/nfcd and apply the patch you provided in this bug, I cannot reproduce this bug after trying more than 50 times.

I attach a nfcd with more debug information, if you still can reproduce it could you help me replace the nfcd and dump the log for me again ? Thanks for help

Comment 26

[arno]

Attachment: Debug log: Hs not sent

I updated to the latest b2g/master as well and used your version of nfcd. I ran into the problem again. Attached are the logs.

Comment 27

[Kamil Leszczuk [:kamituel]]

Hi All,

When working on 948823, I've accidently introduced a bug of calling |doConnect| instead of |_doConnect| in NfcHandoverManager.

This is already fixed in 2.1, and I've requested uplift for 2.0: https://bugzilla.mozilla.org/show_bug.cgi?id=1046289

From the comments in this bug I suspect it's not related, but in any case I wanted you to be aware of that.

Comment 28

[arno]

(In reply to Kamil Leszczuk [:kamituel] from comment #27)
> When working on 948823, I've accidently introduced a bug of calling
> |doConnect| instead of |_doConnect| in NfcHandoverManager.

Thanks for the heads up. Shawn already told me about that issue. Fortunately (or unfortunately, depending on your view) this is unrelated to this bug.

Comment 29

[Dimi Lee [ooo 16.04 - 21.04］]

Attachment: debug nfcd v2

Hi Arno,
  Thanks for help, according to the log, one nfcd internal thread is stuck.
Because the log only contains the info after thread is stuck, so i cannot get enough information.
   Could you help me dump the log again with the uploaded nfcd v2, and dump the log with "-v threadtime" and dump from beginning to the error occurs.
   I am sorry that i tried to check it at my side but i just cannot reproduce it.

Comment 30

[Vincent Chang[:vchang][changyihsin]]

Hi there, is the root cause for this bug is related to nfcd? If not, we should file the new bug to track thread gets stuck issue.

Comment 31

[arno]

(In reply to Dimi Lee[:dimi][:dlee] from comment #29)
>    Could you help me dump the log again with the uploaded nfcd v2, and dump
> the log with "-v threadtime" and dump from beginning to the error occurs.
>    I am sorry that i tried to check it at my side but i just cannot
> reproduce it.

Dimi: I can reproduce this with the v2.0 branch. I've used your new debug version of nfcd and created a log as you've requested. I took the complete log since boot. I managed to transfer two files and on the third attempt, I encountered the missing Hs record problem. Hope this helps.

Comment 32

[arno]

Attachment: Log showing a successful sending of an Hs record with nfcd v2

Comment 33

[arno]

I spent some time testing sharing between two Flame devices. I was able to share 35 pictures (BT on) without one failure. I had to increase the connection timeout as I already suggested in comment 8. HOWEVER, we have some issues with the shrinking UI that prevents sharing from working consistently. This is unrelated to this bug and Sid will open a new bug for this.

Gecko: 8dc28b29aa49f0e80e513ea3b96ad85b0f283d71
Gaia: https://github.com/svic/gaia/tree/Bug_1043856

Comment 34

[Dimi Lee [ooo 16.04 - 21.04］]

Attachment: debug nfcd v3

Hi Arno,
Thanks for help, I might found the root cause. Could you help use upload nfcd v3 to check if the issue can still be reproduced ?

Comment 35

[Alison Shiue]

Hi Arno,

I tried today's 2.0 build with different base images
Gaia      7e71fb4d7399e6ca502f252ab259b5462ef41a1d				
Gecko     https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/b23198eb9bd5				
BuildID   20140805160203				
Version   32.0			
*************************************************
Full flash from pvt	
-------------------
[Both phones BT on]
Pass - 14
Fail - 21 (17 show BT transfer request dialog)

[Both phones BT off]
Pass - 13
Fail - 22 (0 show BT transfer request dialog)
-------------------
V123
-------------------
[Both phones BT on]
Pass - 20
Fail - 15 (13 show BT transfer request dialog)

[Both phones BT off]
Pass - 13
Fail - 22 (0 show BT transfer request dialog)
-------------------
V122
-------------------
[Both phones BT on]
Pass - 16
Fail - 19 (18 show BT transfer request dialog)

[Both phones BT off]
Pass - 15
Fail - 20 (0 show BT transfer request dialog)
*************************************************

The test steps are really simple:
1. Flash test device and enable NFC
(turn on BT if I test BT on scenario)
2. Go to Camera take a picture
3. Go to Gallery and select the picure
4. Tap 2 phones together to share the image
5. Repeat step4 35 times

Do you find any difference between your test and mine?

Comment 36

[arno]

(In reply to ashiue from comment #35)
> Do you find any difference between your test and mine?

Yes, the difference is that I've increased the connection timeout for my testing (see comment 33). The patch I already proposed in comment 8 is needed. Since the original patch was backed out again, I will submit another review from Alive.

Comment 37

[arno]

Attachment: Increase handover timeout

The connection timeout is needed.

Comment 38

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

Comment on attachment 8468900 [details] [review]
Increase handover timeout

Will we change this 20 more times(joking)?

Comment 39

[arno]

(In reply to Dimi Lee[:dimi][:dlee] from comment #34)
> Thanks for help, I might found the root cause. Could you help use upload
> nfcd v3 to check if the issue can still be reproduced ?

Dimi: good news! I no longer get the error with your latest version of nfcd. Nice job! Just out of curiosity: why did the problem only happen from Android to Flame but not between two Flame devices?

Comment 40

[Dimi Lee [ooo 16.04 - 21.04］]

(In reply to arno from comment #39)
> (In reply to Dimi Lee[:dimi][:dlee] from comment #34)
> > Thanks for help, I might found the root cause. Could you help use upload
> > nfcd v3 to check if the issue can still be reproduced ?
> 
> Dimi: good news! I no longer get the error with your latest version of nfcd.
> Nice job! Just out of curiosity: why did the problem only happen from
> Android to Flame but not between two Flame devices?

It seems related to some nci event libnfc-nci received. I would guess the event only triggered by the Android device.

Comment 41

[Dimi Lee [ooo 16.04 - 21.04］]

(In reply to Dimi Lee[:dimi][:dlee] from comment #40)
> (In reply to arno from comment #39)
> > (In reply to Dimi Lee[:dimi][:dlee] from comment #34)
> > > Thanks for help, I might found the root cause. Could you help use upload
> > > nfcd v3 to check if the issue can still be reproduced ?
> > 
> > Dimi: good news! I no longer get the error with your latest version of nfcd.
> > Nice job! Just out of curiosity: why did the problem only happen from
> > Android to Flame but not between two Flame devices?
> 
> It seems related to some nci event libnfc-nci received. I would guess the
> event only triggered by the Android device.

Create Bug 1050621 to track it

Comment 42

[Ryan VanderMeulen [:RyanVM]]

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

Comment 43

[Ryan VanderMeulen [:RyanVM]]

The timeout is already 9000 on v2.0, so there's nothing to uplift there.

Comment 44

[Ryan VanderMeulen [:RyanVM]]

oh ffs, that's because comment 42 was to v2.0, not master.

Master: https://github.com/mozilla-b2g/gaia/commit/8aff4c9d819544ddf8f1fa0928e5bb532aeab617

Arno, in the future, please submit PRs against master.

Comment 45

[Alison Shiue]

Hi Arno,
I tried full flash 2.0 build
Gaia      de28796a8956a48bb98ca67df6a33e0622d642d1
Gecko     https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/5256345f62bd
BuildID   20140810160202
Version   32.0

[Both phones BT on]
Pass - 32
Fail - 3 (0 show BT transfer request dialog)

[Both phones BT off]
Pass - 33
Fail - 2 (0 show BT transfer request dialog)

No longer show the BT transger request dialog at 2.0 latest build.
I would check 2.1 again after bug 1048093 fixed.

And I found a problem when I tried transfer file many times for this issue, I updated at bug 1043878.

Comment 46

[Alison Shiue]

It's good to see the latest 2.1 build also could not reproduce this BT request dialog problem! 
Gaia      8f955d80d175e52283275d3197e4eae2574b389f
Gecko     https://hg.mozilla.org/mozilla-central/rev/391f42c733fc
BuildID   20140811160202
Version   34.0a1

Comment 48

[Lance（leave from Mozilla）]

This issue has been verified successfully on Flame 2.0.
See attachment: 1535.MP4

Step:
1. Launch sender Camera, and take a picture.
2. Go to sender Gallery and select the picure.
3. Tap 2 phones together to share the image.
4. Repeat step4 35 times.

Actual result:
[Both phones BT on]
Pass - 35
Fail - 0 (0 show BT transfer request dialog)

[Both phones BT off]
Pass - 35
Fail - 0 (0 show BT transfer request dialog)

Flame 2.0 version:
Gaia-Rev        856863962362030174bae4e03d59c3ebbc182473
Gecko-Rev       https://hg.mozilla.org/releases/mozilla-2g32_v2_0/rev/e40fe21e37f1
Build-ID        20141207000206
Version         32.0
Device-Name     flame
FW-Release      4.4.2
FW-Incremental  eng.cltbld.20141207.034341
FW-Date         Sun Dec  7 03:43:52 EST 2014
Bootloader      L1TC00011880

Comment 49

[Lance（leave from Mozilla）]

Attachment: 1535.MP4