984197 - [Sora][Wi-Fi]DUT connect the AP not smoothly through PBC WPS

Status: RESOLVED WORKSFORME

(Firefox OS Graveyard :: Wifi, defect, P2)

Description

[sync-1]

Mozilla build ID: 20140226004002
 Created an attachment (id=662402)
 refer the attachment
 
 DEFECT DESCRIPTION:
  DUT connect the AP not smoothly through  PBC WPS .
 
  REPRODUCING PROCEDURES:
  1,Home->Setting->enable Wi-Fi->Connect the AP through  PBC WPS->DUT connect the AP not smoothly-> KO
 Note:Bettle lite is ok.V10G is ok.
  EXPECTED BEHAVIOUR:
  DUT connect the AP not smoothly through  PBC WPS .
  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: refer the attachment

Comment 2

[Wang Rong]

Please help check. I don't know what change makes pbc work abnormally.

Comment 3

[Jason Smith [:jsmith]]

What do you mean by not smoothly? Can you be more specific here?

Comment 4

[Wang Rong]

I tested it many times and find this regular pattern.

When the screen turn off after pbc button be pressed, it triggers active scan, then the wps negotiation is going on. But if the screen is keep lighting after pbc button be pressed, there is no wps negotiation and wps will be time out.

Comment 5

[Jason Smith [:jsmith]]

Vance - Can you find out if TCL sees this as a cert blocker or not?

Comment 6

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

No this is not a certification blocker

Comment 7

[Wang Rong]

Vendor checked this problem and suspect that the reason for this problem is that command "scan" not issued.

blew is vendor's comment, please help check.

I tested on my device: When I click wps buttong on wifi setting UI,  framework will issue below commands:
9017: 03-20 11:24:37.256 D/wpa_supplicant( 1141): wlan0: Control interface command 'WPS_PBC'
9241: 03-20 11:24:37.346 D/wpa_supplicant( 1141): wlan0: Control interface command 'SET ps 1'
9249: 03-20 11:24:37.346 D/wpa_supplicant( 1141): wlan0: Control interface command 'DRIVER BTCOEXMODE 2'
12131: 03-20 11:24:37.876 D/wpa_supplicant( 1141): wlan0: Control interface command 'BSS RANGE=0- MASK=0x21987'
12563: 03-20 11:24:43.876 D/wpa_supplicant( 1141): wlan0: Control interface command 'SCAN'
14481: 03-20 11:24:44.426 D/wpa_supplicant( 1141): wlan0: Control interface command 'BSS RANGE=0- MASK=0x21987'
14787: 03-20 11:24:53.876 D/wpa_supplicant( 1141): wlan0: Control interface command 'SCAN'
16675: 03-20 11:24:54.486 D/wpa_supplicant( 1141): wlan0: Control interface command 'BSS RANGE=0- MASK=0x21987'


So the problem should be the Firefox framework didn't issue SCAN commands after WPS_PBC.

Comment 8

[Chuck Lee [:chucklee, Triggered by NI, Review, and Feedback requests]]

I don't think the scan command would imporve anything because wpa_supplicant will start active scan right after WPS_PBC command:
03-11 16:45:05.693 D/wpa_supplicant( 2861): RX ctrl_iface - hexdump(len=7): 57 50 53 5f 50 42 43
03-11 16:45:05.693 D/wpa_supplicant( 2861): wlan0: Control interface command 'WPS_PBC'
...
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS: Building WPS IE for Probe Request
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Version (hardcoded 0x10)
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Request Type
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Config Methods (2108)
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * UUID-E
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Primary Device Type
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * RF Bands (3)
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Association State
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Configuration Error (0)
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Device Password ID (4)
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Manufacturer
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Model Name
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Model Number
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Device Name
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Version2 (0x20)
03-11 16:45:05.823 D/wpa_supplicant( 2861): WPS:  * Request to Enroll (1)
03-11 16:45:05.823 D/wpa_supplicant( 2861): P2P: * P2P IE header
03-11 16:45:05.823 D/wpa_supplicant( 2861): P2P: * Capability dev=25 group=00
03-11 16:45:05.823 D/wpa_supplicant( 2861): P2P: * Listen Channel: Regulatory Class 81 Channel 11
03-11 16:45:05.823 D/wpa_supplicant( 2861): wlan0: Optimize scan based on previously generated frequency list
03-11 16:45:05.823 D/wpa_supplicant( 2861): wlan0: nl80211: scan request
03-11 16:45:05.823 D/wpa_supplicant( 2861): nl80211: Scan SSID - hexdump(len=0): [NULL]
03-11 16:45:05.823 D/wpa_supplicant( 2861): nl80211: Scan extra IEs - hexdump(len=129): dd 6c 00 50 f2 04 10 4a 00 01 10 10 3a 00 01 01 10 08 00 02 21 08 10 47 00 10 ae 38 db 4f b9 be ...
03-11 16:45:05.823 D/wpa_supplicant( 2861): nl80211: Scan frequency 2412 MHz
03-11 16:45:05.823 D/wpa_supplicant( 2861): nl80211: Scan frequency 2437 MHz


Also, there's a scan command right after:
03-11 16:45:05.863 D/wpa_supplicant( 2861): wlan0: Control interface command 'SCAN'


Based on the log, it seems that WPS APs are found but all disabled:
03-11 16:45:06.123 D/wpa_supplicant( 2861): WPS: AP 20:aa:4b:8d:e7:e8 type 0 added
...
03-11 16:45:06.123 D/wpa_supplicant( 2861): WPS: AP 00:22:6b:46:e7:98 type 0 added
03-11 16:45:06.123 D/wpa_supplicant( 2861): WPS: AP[0] 20:aa:4b:8d:e7:e8 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
03-11 16:45:06.123 D/wpa_supplicant( 2861): WPS: AP[1] 00:22:6b:46:e7:98 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
...
03-11 16:45:06.123 D/wpa_supplicant( 2861): wlan0: 0: 20:aa:4b:8d:e7:e8 ssid='peter24' wpa_ie_len=22 rsn_ie_len=20 caps=0x431 level=-30 wps
03-11 16:45:06.123 D/wpa_supplicant( 2861): wlan0:    skip - disabled
03-11 16:45:06.123 D/wpa_supplicant( 2861): wlan0: 1: 00:22:6b:46:e7:98 ssid='stremtest' wpa_ie_len=28 rsn_ie_len=24 caps=0x411 level=-66 wps
03-11 16:45:06.123 D/wpa_supplicant( 2861): wlan0:    skip - disabled

Then it took 5 seconds to select an AP:
03-11 16:45:11.653 D/wpa_supplicant( 2861): wlan0:    selected BSS 20:aa:4b:8d:e7:e8 ssid='peter24'

There's no command to disable network in the log, so they are likely being disabled by wpa_supplicant.

Comment 9

[Chuck Lee [:chucklee, Triggered by NI, Review, and Feedback requests]]

Then wpa_supplicant starts the handshake:
03-11 16:45:12.903 D/wpa_supplicant( 2861): EAPOL: startWhen --> 0
03-11 16:45:12.903 D/wpa_supplicant( 2861): EAPOL: SUPP_PAE entering state CONNECTING
03-11 16:45:12.903 D/wpa_supplicant( 2861): EAPOL: txStart
03-11 16:45:12.903 D/wpa_supplicant( 2861): TX EAPOL: dst=20:aa:4b:8d:e7:e8
03-11 16:45:12.903 D/wpa_supplicant( 2861): TX EAPOL - hexdump(len=4): 01 01 00 00
03-11 16:45:12.913 D/wpa_supplicant( 2861): wlan0: RX EAPOL from 20:aa:4b:8d:e7:e8
03-11 16:45:12.913 D/wpa_supplicant( 2861): RX EAPOL - hexdump(len=9): 02 00 00 05 01 cd 00 05 01
03-11 16:45:12.913 D/wpa_supplicant( 2861): wlan0: Setting authentication timeout: 70 sec 0 usec
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: Received EAP-Packet frame
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: SUPP_PAE entering state RESTART
...
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: SUPP_BE entering state RESPONSE
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: txSuppRsp
03-11 16:45:12.913 D/wpa_supplicant( 2861): TX EAPOL: dst=20:aa:4b:8d:e7:e8
03-11 16:45:12.913 D/wpa_supplicant( 2861): TX EAPOL - hexdump(len=38): 01 00 00 22 02 cd 00 22 01 57 46 41 2d 53 69 6d 70 6c 65 43 6f 6e 66 69 67 2d 45 6e 72 6f 6c 6c ...
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: SUPP_BE entering state RECEIVE
03-11 16:45:12.913 D/wpa_supplicant( 2861): wlan0: RX EAPOL from 20:aa:4b:8d:e7:e8
03-11 16:45:12.913 D/wpa_supplicant( 2861): RX EAPOL - hexdump(len=18): 02 00 00 0e 01 ce 00 0e fe 00 37 2a 00 00 00 01 01 00
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: Received EAP-Packet frame
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: SUPP_BE entering state REQUEST
...
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: SUPP_BE entering state RESPONSE
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: txSuppRsp
03-11 16:45:12.913 D/wpa_supplicant( 2861): TX EAPOL: dst=20:aa:4b:8d:e7:e8
03-11 16:45:12.913 D/wpa_supplicant( 2861): TX EAPOL - hexdump(len=38): 01 00 00 22 02 cd 00 22 01 57 46 41 2d 53 69 6d 70 6c 65 43 6f 6e 66 69 67 2d 45 6e 72 6f 6c 6c ...
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: SUPP_BE entering state RECEIVE
03-11 16:45:12.913 D/wpa_supplicant( 2861): wlan0: RX EAPOL from 20:aa:4b:8d:e7:e8
03-11 16:45:12.913 D/wpa_supplicant( 2861): RX EAPOL - hexdump(len=18): 02 00 00 0e 01 ce 00 0e fe 00 37 2a 00 00 00 01 01 00
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: Received EAP-Packet frame
03-11 16:45:12.913 D/wpa_supplicant( 2861): EAPOL: SUPP_BE entering state REQUEST


And handshake fails for several times:
03-11 16:45:13.003 D/wpa_supplicant( 2861): EAP-WSC: MESG -> MESG
03-11 16:45:13.003 D/wpa_supplicant( 2861): EAP-WSC: Generating Response
03-11 16:45:13.003 D/wpa_supplicant( 2861): EAP-WSC: Sending out 362 bytes (message sent completely)
03-11 16:45:13.003 D/wpa_supplicant( 2861): EAP-WSC: MESG -> MESG
03-11 16:45:13.003 D/wpa_supplicant( 2861): EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL
03-11 16:45:13.003 D/wpa_supplicant( 2861): EAP: EAP entering state SEND_RESPONSE
03-11 16:45:13.003 D/wpa_supplicant( 2861): EAP: EAP entering state IDLE
03-11 16:45:13.003 D/wpa_supplicant( 2861): EAPOL: SUPP_BE entering state RESPONSE
03-11 16:45:13.003 D/wpa_supplicant( 2861): EAPOL: txSuppRsp
03-11 16:45:13.003 D/wpa_supplicant( 2861): TX EAPOL: dst=20:aa:4b:8d:e7:e8


And ended up fail:
03-11 16:45:13.603 D/wpa_supplicant( 2861): TX EAPOL: dst=20:aa:4b:8d:e7:e8
03-11 16:45:13.603 D/wpa_supplicant( 2861): TX EAPOL - hexdump(len=78): 01 00 00 4a 02 d2 00 4a fe 00 37 2a 00 00 00 01 05 00 10 4a 00 01 10 10 22 00 01 0f 10 1a 00 10 ...
03-11 16:45:13.603 D/wpa_supplicant( 2861): EAPOL: SUPP_BE entering state RECEIVE
03-11 16:45:13.623 D/wpa_supplicant( 2861): wlan0: RX EAPOL from 20:aa:4b:8d:e7:e8
03-11 16:45:13.623 D/wpa_supplicant( 2861): RX EAPOL - hexdump(len=8): 02 00 00 04 04 d2 00 04
03-11 16:45:13.623 D/wpa_supplicant( 2861): EAPOL: Received EAP-Packet frame
03-11 16:45:13.623 D/wpa_supplicant( 2861): EAPOL: SUPP_BE entering state REQUEST
03-11 16:45:13.623 D/wpa_supplicant( 2861): EAPOL: getSuppRsp
03-11 16:45:13.623 D/wpa_supplicant( 2861): EAP: EAP entering state RECEIVED
03-11 16:45:13.623 D/wpa_supplicant( 2861): EAP: Received EAP-Failure

Comment 10

[Chuck Lee [:chucklee, Triggered by NI, Review, and Feedback requests]]

Based on analysis above, I think the "not smoothly" might caused by
1. AP is disabled for 5 seconds by wpa_supplicant.
2. WPS handshake failed.
And is more related to wpa_supplicant than gecko.

There's some command that didn't issued by Firefox OS including 'SET ps 1', 'DRIVER BTCOEXMODE 2', 'BSS RANGE=0- MASK=0x21987', but I don't have devices to test them(Sora and AP).

I think if you could help test the connect commands in comment 7 through wpa_cli on sora, and help us to find the main difference.

Comment 11

[Wang Rong]

The screen turn off and then turn on, or I scan manually, these operations all can trigger the wps negotiation but if I don't do these, wps negotiation will not begin. The AP which pbc button has been pushed will not be found by STA(logs shows ssid mismatch). Qcom Engineer will check this problem on site.

Comment 12

[Wang Rong]

Below is Qcom engineer's analysis. If it is right, it can explain the behavior we met well. We need confirm that in firefox os design, only scanning manually can trigger active scan and the other time it's always in passive scan mode? 

"From the latest log ,I see we already put extra_ie in probe request. But we didn't search CMT. I suspect current scan mode is passive. this mode will receive beacon but not send probe request to get probe response.

So I want to figure out why SCAN_ACTIVE is not issued when wps button pressed."

Comment 13

[Jason Smith [:jsmith]]

Not a blocker - we already concluded this wasn't a blocker for certification.

Comment 14

[Wang Rong]

This is an urgent(P0) bug of WiFi. Need your support.

Comment 15

[Wang Rong]

We find a way to resolve this bug. I tested it several times and didn't find problems. Please help us review this code. If you think it's ok, please close this PR. Thanks.

In gecko/dom/wifi/WifiCommand.jsm line138:

  command.wpsPbc = function (callback) {
    doBooleanCommand("WPS_PBC", "OK", callback);
+    doBooleanCommand("DRIVER SCAN-ACTIVE", "OK", callback);
 +   doBooleanCommand("SCAN", "OK", callback);
  };

Comment 16

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

Hi Chuck -

Wang Rong manage to find a way to fix this problem, could you help to review his modification in Comment#15 to see if you have any concern?

Appreciate your help

Vance

Comment 17

[Chuck Lee [:chucklee, Triggered by NI, Review, and Feedback requests]]

(In reply to Wang Rong from comment #15)
> We find a way to resolve this bug. I tested it several times and didn't find
> problems. Please help us review this code. If you think it's ok, please
> close this PR. Thanks.
> 
> In gecko/dom/wifi/WifiCommand.jsm line138:
> 
>   command.wpsPbc = function (callback) {
>     doBooleanCommand("WPS_PBC", "OK", callback);
> +    doBooleanCommand("DRIVER SCAN-ACTIVE", "OK", callback);
>  +   doBooleanCommand("SCAN", "OK", callback);
>   };

Please upload patch as attachment instead of post code directly.

We try to keep scan in passive mode for less power consumption, also this patch will make |callback| being called for three times.
So it should be written like
doBooleanCommand("WPS_PBC", "OK", function(ok){
  if (!ok) {
    callback(false);
    return;
  }

  doBooleanCommand("DRIVER SCAN-ACTIVE", "OK", function(){
    doBooleanCommand("SCAN", "OK", function() {
      doBooleanCommand("DRIVER SCAN-PASSIVE", "OK", function(){
      });
    });
  });

  callback(true);
});

But I like to put this command chain in WifiWorker instead of WifiCommand, I'll discuss this with vincent.

Comment 18

[Chuck Lee [:chucklee, Triggered by NI, Review, and Feedback requests]]

Though I still think triggering active scan might not be the right way, the main cause should be why APs are disabled after WPS_PBC command, as comment 8.

> 03-11 16:45:06.123 D/wpa_supplicant( 2861): wlan0: 0: 20:aa:4b:8d:e7:e8 ssid='peter24' wpa_ie_len=22 rsn_ie_len=20 caps=0x431 level=-30 wps
> 03-11 16:45:06.123 D/wpa_supplicant( 2861): wlan0:    skip - disabled
> 03-11 16:45:06.123 D/wpa_supplicant( 2861): wlan0: 1: 00:22:6b:46:e7:98 ssid='stremtest' wpa_ie_len=28 rsn_ie_len=24 caps=0x411 level=-66 wps
> 03-11 16:45:06.123 D/wpa_supplicant( 2861): wlan0:    skip - disabled

Maybe you can test if PBC still works fine after using command "ENABLE_NETWORK ALL"(if you supplicant supports) instead of active scan.

Comment 19

[Wang Rong]

Attachment: fail adb log

We compared lots of fail and successful log then had this conclusion of active scan not issued. Please check this fail log, I didn't find AP diabled in this log. Thanks.

Comment 20

[Wang Rong]

Attachment: after scan manually, pbc connect successfully

This is a log of starting scan manually after pbc button pushed.

Comment 21

[Vincent Chang[:vchang][changyihsin]]

Hi Wang Rong, may I know the reason why wpa_supplicant needs active scan command to make wpa_pbc works ?

Comment 22

[Wang Rong]

Please refer to comment 12. Qcom Engineer give an explanation for this.

Comment 23

[Chuck Lee [:chucklee, Triggered by NI, Review, and Feedback requests]]

Passive scan should find every AP, except it is has special settings like hide SSID, long beacon interval, or only sending beacon while WPS is activated.
I don't know if the testing AP in this bug has these behaviors and make it invisible to passive scan. If so, using active scan do help.
But in fail log, attachment 8397614 [details], 'CMT' is already in AP list(maybe left by previous active scan, whatever), the connection still failed due to SSID mistach.

Last time we test WPS-PBC is on unagi and it works fine(except the AP PIN), I like to ask QA to test WPS on Buri again to check if this is a common problem need to be fixed on central.

Comment 24

[Chuck Lee [:chucklee, Triggered by NI, Review, and Feedback requests]]

I don't have the AP for testing, did QA test Wifi WPS-PBC function on Buri in recent time?
If so, please provide your test result.
If not, please help test Wifi WPS-PBC function on Buri based on v1.3, v1.4 and central.

Thank you for your help!

Comment 25

[Jason Smith [:jsmith]]

(In reply to Chuck Lee [:chucklee] from comment #24)
> I don't have the AP for testing, did QA test Wifi WPS-PBC function on Buri
> in recent time?
> If so, please provide your test result.
> If not, please help test Wifi WPS-PBC function on Buri based on v1.3, v1.4
> and central.
> 
> Thank you for your help!

I don't think we've got this setup. If you need QA support here, then I'd suggest asking the reporter here for help on the testing you need.

Comment 26

[Ken Chang[:kenkai]]

According to comment 25, maybe report is willing to help.

Comment 27

[sync-1]

What help do you need?

Comment 28

[Wang Rong]

Please close this PR. This has be fixed. Many thanks.