Closed
Bug 1151726
Opened 9 years ago
Closed 9 years ago
[Wifi] TEST-UNEXPECTED-ERROR | test_wifi_associate_WPA_EAP_TTLS.js | ScriptTimeoutException: ScriptTimeoutException: timed out
Categories
(Firefox OS Graveyard :: Wifi, defect)
Tracking
(tracking-b2g:backlog, firefox41 fixed)
Tracking | Status | |
---|---|---|
firefox41 | --- | fixed |
People
(Reporter: edgar, Assigned: edgar)
References
Details
Attachments
(1 file)
1012 bytes,
patch
|
hchang
:
review+
|
Details | Diff | Splinter Review |
+++ 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 | ||
Comment 1•9 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
Comment 4•9 years ago
|
||
This test is pretty much permafail on b2g turning them off gets us https://treeherder.mozilla.org/#/jobs?repo=try&revision=8d93456f300b&exclusion_profile=false vs https://treeherder.mozilla.org/#/jobs?repo=try&revision=f94a506612cd&exclusion_profile=false
> 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.
Comment 7•9 years ago
|
||
(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 (Legacy TBPL/Treeherder Robot) |
Comment hidden (Legacy TBPL/Treeherder Robot) |
Comment 11•9 years ago
|
||
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•9 years ago
|
Flags: needinfo?(kli)
Comment 12•9 years ago
|
||
Let's see if urandom fixes all the EAP test case failure. https://treeherder.mozilla.org/#/jobs?repo=try&revision=9be9804afe53
Comment 13•9 years ago
|
||
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.
Comment 14•9 years ago
|
||
(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!
Comment 15•9 years ago
|
||
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.
Comment 16•9 years ago
|
||
/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.
Comment 17•9 years ago
|
||
(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.
Comment 18•9 years ago
|
||
(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 | ||
Comment 19•9 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•9 years ago
|
||
Henry, mind reviewing this? Thank you.
Attachment #8620864 -
Flags: review?(hchang)
Assignee | ||
Updated•9 years ago
|
Assignee: nobody → echen
Updated•9 years ago
|
Attachment #8620864 -
Flags: review?(hchang) → review+
Assignee | ||
Comment 21•9 years ago
|
||
Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=75c8329af768&exclusion_profile=false
https://hg.mozilla.org/mozilla-central/rev/0a965bb6794a
Status: NEW → RESOLVED
Closed: 9 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.
Description
•