bugzilla.mozilla.org has resumed normal operation. Attachments prior to 2014 will be unavailable for a few days. This is tracked in Bug 1475801.
Please report any other irregularities here.

[Wifi] TEST-UNEXPECTED-ERROR | test_wifi_associate_WPA_EAP_TTLS.js | ScriptTimeoutException: ScriptTimeoutException: timed out

RESOLVED FIXED in Firefox 41

Status

Firefox OS
Wifi
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: edgar, Assigned: edgar)

Tracking

unspecified
2.2 S14 (12june)
All
Gonk (Firefox OS)
Dependency tree / graph

Firefox Tracking Flags

(tracking-b2g:backlog, firefox41 fixed)

Details

Attachments

(1 attachment)

(Assignee)

Description

3 years ago
+++ This bug was initially created as a follow-up of Bug #1084230 +++

test_wifi_associate_WPA_EAP_TTLS.js is not stable, https://treeherder.mozilla.org/#/jobs?repo=b2g-inbound&filter-searchStr=MNW&exclusion_profile=false, it is easy to get timeout.
(Assignee)

Updated

3 years ago
Blocks: 1081529
(Assignee)

Comment 1

3 years ago
Looks like the test sometimes takes too long to finish (https://treeherder.mozilla.org/logviewer.html#?job_id=1667472&repo=b2g-inbound takes 66514ms to finish).
Let's see if increasing the MARIONETTE_TIMEOUT helps: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ebe26c3a68dc&exclusion_profile=false
After comparing logs, it seems the EAP succeeded on every connection attempt, but wpa_supplicant received something from hostapd to make it disconnecting instead of continuing handshaking:

[ Log for connection fail ]
> 19:18:07     INFO -  04-07 02:13:19.267 I/hostapd ( 2717): AP-0: CTRL-EVENT-EAP-SUCCESS 02:b0:0a:4b:0f:f0
> 19:18:07     INFO -  04-07 02:13:19.267 D/wpa_supplicant( 2443): test_driver: received 28 bytes
> ...
> 19:18:07     INFO -  04-07 02:13:19.267 I/wpa_supplicant( 2443): wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
> ...
> 19:18:07     INFO -  04-07 02:13:19.287 D/wpa_supplicant( 2443): test_driver: received 6 bytes
> 19:18:07     INFO -  04-07 02:13:19.287 D/wpa_supplicant( 2443): Added BSSID 02:32:d4:66:49:92 into blacklist

[ Log for connection succeed ]
> 20:00:37     INFO -  04-07 02:56:04.205 I/hostapd ( 2713): AP-0: CTRL-EVENT-EAP-SUCCESS 02:b0:0a:4b:0f:f0
> 20:00:37     INFO -  04-07 02:56:04.205 D/wpa_supplicant( 2439): test_driver: received 28 bytes
> ...
> 20:00:37     INFO -  04-07 02:56:04.205 I/wpa_supplicant( 2439): wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
> ...
> 20:00:37     INFO -  04-07 02:56:04.235 D/wpa_supplicant( 2439): test_driver: received 205 bytes
> ...
> 20:00:37     INFO -  04-07 02:56:04.235 I/wpa_supplicant( 2439): wlan0: CTRL-EVENT-CONNECTED - Connection to 02:32:d4:66:49:92 completed (reauth) [id=0 id_str=]


Also some EAP failures like:
> 20:00:37     INFO -  04-07 02:55:58.965 D/wpa_supplicant( 2439): EAP-TTLS: received 90 bytes encrypted data for Phase 2
> 20:00:37     INFO -  04-07 02:55:58.965 D/wpa_supplicant( 2439): EAP-TTLS: AVP: code=2 flags=0xc0 length=18
> 20:00:37     INFO -  04-07 02:55:58.965 D/wpa_supplicant( 2439): EAP-TTLS: AVP vendor_id 311
> 20:00:37     INFO -  04-07 02:55:58.965 D/wpa_supplicant( 2439): EAP-TTLS/MSCHAPV2: Received MS-CHAP-Error - failed
Comparing to EAP success:
> 20:00:37     INFO -  04-07 02:56:04.135 D/wpa_supplicant( 2439): EAP-TTLS: TLS done, proceed to Phase 2
> 20:00:37     INFO -  04-07 02:56:04.135 D/wpa_supplicant( 2439): EAP-TTLS: received 0 bytes encrypted data for Phase 2
> 20:00:37     INFO -  04-07 02:56:04.135 D/wpa_supplicant( 2439): EAP-TTLS: empty data in beginning of Phase 2 - use fake EAP-Request Identity
> 20:00:37     INFO -  04-07 02:56:04.135 D/wpa_supplicant( 2439): EAP-TTLS: Phase 2 MSCHAPV2 Request
> 20:00:37     INFO -  04-07 02:56:04.155 D/wpa_supplicant( 2439): EAP-TTLS/MSCHAPV2: EAP workaround - allow success without tunneled response
> 20:00:37     INFO -  04-07 02:56:04.155 D/wpa_supplicant( 2439): SSL: 186 bytes left to be sent out (of total 186 bytes)
> 20:00:37     INFO -  04-07 02:56:04.155 D/wpa_supplicant( 2439): EAP-TTLS: Authentication completed successfully (MAY_CONT)



But these logs are presented in both success and failed test logs, I don't see any patterns on who or how to trigger these error.
Increase timeout might help for giving it more change to retry, but the root cause might be in wpa_supplicant.
I'll try look to into it.
Errata for the EAP success/failure comparison:
EAP success
> 20:00:37     INFO -  04-07 02:56:04.175 D/wpa_supplicant( 2439): EAP-TTLS: received 122 bytes encrypted data for Phase 2
> 20:00:37     INFO -  04-07 02:56:04.175 D/wpa_supplicant( 2439): EAP-TTLS: AVP: code=26 flags=0xc0 length=55
> 20:00:37     INFO -  04-07 02:56:04.175 D/wpa_supplicant( 2439): EAP-TTLS: AVP vendor_id 311
> 20:00:37     INFO -  04-07 02:56:04.175 I/wpa_supplicant( 2439): EAP-TTLS: Phase 2 MSCHAPV2 authentication succeeded
> 20:00:37     INFO -  04-07 02:56:04.175 D/wpa_supplicant( 2439): EAP-TTLS: Authentication completed successfully

EAP fail
> 20:00:37     INFO -  04-07 02:55:53.825 D/wpa_supplicant( 2439): EAP-TTLS: received 90 bytes encrypted data for Phase 2
> 20:00:37     INFO -  04-07 02:55:53.825 D/wpa_supplicant( 2439): EAP-TTLS: AVP: code=2 flags=0xc0 length=18
> 20:00:37     INFO -  04-07 02:55:53.825 D/wpa_supplicant( 2439): EAP-TTLS: AVP vendor_id 311
> 20:00:37     INFO -  04-07 02:55:53.825 D/wpa_supplicant( 2439): EAP-TTLS/MSCHAPV2: Received MS-CHAP-Error - failed
> 13:19.267 I/hostapd ( 2717): AP-0: CTRL-EVENT-EAP-SUCCESS 02:b0:0a:4b:0f:f0
> 19:18:07     INFO -  04-07 02:13:19.267 D/wpa_supplicant( 2443): test_driver: received 28 bytes
> ...
> 19:18:07     INFO -  04-07 02:13:19.267 I/wpa_supplicant( 2443): wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
> ...
> 19:18:07     INFO -  04-07 02:13:19.287 D/wpa_supplicant( 2443): test_driver: received 6 bytes
> 19:18:07     INFO -  04-07 02:13:19.287 D/wpa_supplicant( 2443): Added BSSID 02:32:d4:66:49:92 into blacklist

After enabling more log, the cause of disconnection above is /dev/random of ICS emulator doesn't work, so hostpad try to get entropy for random generator:
> D/hostapd (  371): WPA: Reject 4-way handshake to collect more entropy for random number generation
> D/hostapd (  371): random: Mark internal entropy pool to be ready (count=2/2)
> D/hostapd (  371): hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 02:b0:0a:4b:0f:f0 reason 2

If we can fix /dev/random on emulator(or use /dev/urandom instead), there will be much less unnecessary retry, and the success rate might be much higher.
[Tracking Requested - why for this release]:
tracking-b2g: --- → backlog
(In reply to Chuck Lee [:chucklee, OOO forever, will response to NI, Review, and Feedback requests] from comment #5)
> > 13:19.267 I/hostapd ( 2717): AP-0: CTRL-EVENT-EAP-SUCCESS 02:b0:0a:4b:0f:f0
> > 19:18:07     INFO -  04-07 02:13:19.267 D/wpa_supplicant( 2443): test_driver: received 28 bytes
> > ...
> > 19:18:07     INFO -  04-07 02:13:19.267 I/wpa_supplicant( 2443): wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
> > ...
> > 19:18:07     INFO -  04-07 02:13:19.287 D/wpa_supplicant( 2443): test_driver: received 6 bytes
> > 19:18:07     INFO -  04-07 02:13:19.287 D/wpa_supplicant( 2443): Added BSSID 02:32:d4:66:49:92 into blacklist
> 
> After enabling more log, the cause of disconnection above is /dev/random of
> ICS emulator doesn't work, so hostpad try to get entropy for random
> generator:
> > D/hostapd (  371): WPA: Reject 4-way handshake to collect more entropy for random number generation
> > D/hostapd (  371): random: Mark internal entropy pool to be ready (count=2/2)
> > D/hostapd (  371): hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 02:b0:0a:4b:0f:f0 reason 2
> 
Hi Chuck, can you point us the code where "hostpad try to get entropy for random generator"?
(In reply to Vincent Chang[:vchang] from comment #7)
> (In reply to Chuck Lee [:chucklee, OOO forever, will response to NI, Review,
> and Feedback requests] from comment #5)
> > > 13:19.267 I/hostapd ( 2717): AP-0: CTRL-EVENT-EAP-SUCCESS 02:b0:0a:4b:0f:f0
> > > 19:18:07     INFO -  04-07 02:13:19.267 D/wpa_supplicant( 2443): test_driver: received 28 bytes
> > > ...
> > > 19:18:07     INFO -  04-07 02:13:19.267 I/wpa_supplicant( 2443): wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
> > > ...
> > > 19:18:07     INFO -  04-07 02:13:19.287 D/wpa_supplicant( 2443): test_driver: received 6 bytes
> > > 19:18:07     INFO -  04-07 02:13:19.287 D/wpa_supplicant( 2443): Added BSSID 02:32:d4:66:49:92 into blacklist
> > 
> > After enabling more log, the cause of disconnection above is /dev/random of
> > ICS emulator doesn't work, so hostpad try to get entropy for random
> > generator:
> > > D/hostapd (  371): WPA: Reject 4-way handshake to collect more entropy for random number generation

This log comes from [1], controlled by |sm->group->reject_4way_hs_for_entropy|.
And the variable is controlled by return value of function |random_pool_ready()| [2].
So I looked into the function [3], and try "cat /dev/random" on ICS emulator, it doesn't response.
So it will return error and print log "WPA: Not enough entropy in random pool to proceed - reject first 4-way handshake", this is shown on every EAP test cases, like
> 03:36:00     INFO -  04-14 10:27:34.876 E/hostapd ( 2024): random: Cannot read from /dev/random: Try again
> 03:36:00     INFO -  04-14 10:27:34.876 I/hostapd ( 2024): random: Only 0/20 bytes of strong random data available from /dev/random
> 03:36:00     INFO -  04-14 10:27:34.876 I/hostapd ( 2024): random: Not enough entropy pool available for secure operations
> 03:36:00     INFO -  04-14 10:27:34.876 I/hostapd ( 2024): WPA: Not enough entropy in random pool to proceed - reject first 4-way handshake
If I change /dev/random to /dev/urandom in random.c, then it works fine.

[1] https://android.googlesource.com/platform/external/wpa_supplicant_8/+/master/src/ap/wpa_auth.c#993
[2] https://android.googlesource.com/platform/external/wpa_supplicant_8/+/master/src/ap/wpa_auth.c#1666
[3] https://android.googlesource.com/platform/external/wpa_supplicant_8/+/master/src/crypto/random.c#213


> > > D/hostapd (  371): random: Mark internal entropy pool to be ready (count=2/2)

This log comes from [4].
We didn't set entropy file for hostapd in the test script now, and the disconnection will happen if we provide an empty entropy file, based on the related-code(|| and ||).
I haven't got time to create a dummy entropy file and test if it would work yet.

[4] https://android.googlesource.com/platform/external/wpa_supplicant_8/+/master/src/crypto/random.c#288

> > > D/hostapd (  371): hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA 02:b0:0a:4b:0f:f0 reason 2
> > 
> Hi Chuck, can you point us the code where "hostpad try to get entropy for
> random generator"?
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Hi Seilin,

Could you please mirror the branch 'android-4.0.4_r2.1' from 

git://codeaurora.org/platform/external/wpa_supplicant_8

to 

https://github.com/mozilla-b2g/platform_external_wpa_supplicant_8?

We are going to modify the source code to fix this bug. Thanks!

Updated

3 years ago
Flags: needinfo?(kli)
Let's see if urandom fixes all the EAP test case failure.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=9be9804afe53
Hey!

I just want to add some general thoughts.

 * The emulator's RNG isn't broken. The emulator just doesn't have much random, external input, if any. So the entropy pool of /dev/random is mostly empty. Consequently read operations block.

 * The output of /dev/random is truly random, while /dev/urandom also returns pseudo-random values. There's probably a reason why wpa_supplicant uses /dev/random (for crypto keys?). Changing this is probably OK on the emulator, but not something we should do for real devices. Using an entropy file seems like the better solution to me.
(In reply to Thomas Zimmermann [:tzimmermann] [:tdz] from comment #13)
> Hey!
> 
> I just want to add some general thoughts.
> 
>  * The emulator's RNG isn't broken. The emulator just doesn't have much
> random, external input, if any. So the entropy pool of /dev/random is mostly
> empty. Consequently read operations block.
> 
>  * The output of /dev/random is truly random, while /dev/urandom also
> returns pseudo-random values. There's probably a reason why wpa_supplicant
> uses /dev/random (for crypto keys?). Changing this is probably OK on the
> emulator, but not something we should do for real devices. Using an entropy
> file seems like the better solution to me.

Hi Thomas,

Thanks for your useful information! We will only change to use urandom
for the wap_supplicant used by emulator.

Do you know what else we can do without modifying the source code
(like change the emulator environment) to fix this? Thanks!
Since we don't care about the quality of the randomness, we could make /dev/random always return something.

The cleanest solution is probably to implement QEmu support for an RNG device and write a kernel driver that feeds /dev/random from the device. But I don't know any details without more research.
/dev/random support the ioctl RNDADDENTROPY, which allows user-space programs to add entropy to the pool. It might be a lot easier to simply write pre-recorded data into the RNG.
(In reply to Henry Chang [:henry] from comment #12)
> Let's see if urandom fixes all the EAP test case failure.
> 
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=9be9804afe53

Seems it didn't help.
(In reply to Henry Chang [:henry] from comment #17)
> 
> Seems it didn't help.

When I saw this comment, the new branch was created. Let's leave it there.

https://github.com/mozilla-b2g/platform_external_wpa_supplicant_8/tree/b2g-4.0.4_r2.1
Flags: needinfo?(kli)
(Assignee)

Updated

3 years ago
See Also: → bug 1173697
(Assignee)

Comment 19

3 years ago
Pre offline discuss with Henry, let's just disable the failure tests first. I have filed bug 1173697 to track the failure tests.
(Assignee)

Comment 20

3 years ago
Created attachment 8620864 [details] [diff] [review]
Patch, v1

Henry, mind reviewing this? Thank you.
Attachment #8620864 - Flags: review?(hchang)
(Assignee)

Updated

3 years ago
Assignee: nobody → echen

Updated

3 years ago
Attachment #8620864 - Flags: review?(hchang) → review+
https://hg.mozilla.org/mozilla-central/rev/0a965bb6794a
Status: NEW → RESOLVED
Last Resolved: 3 years ago
status-firefox41: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 2.2 S14 (12june)
You need to log in before you can comment on or make changes to this bug.