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

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Wifi, defect)

Description

[Edgar Chen [:edgar]]

+++ 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.

Comment 1

[Edgar Chen [:edgar]]

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

Comment 2

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

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.

Comment 3

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

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

[David Burns :automatedtester]

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

Comment 5

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

> 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 6

[Wesley Huang [:wesley_huang] (EPM) (NI me)]

[Tracking Requested - why for this release]:

Comment 7

[Vincent Chang[:vchang][changyihsin]]

(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"?

Comment 8

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

(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 9

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=try&job_id=6829790
repository: try
start_time: 2015-04-21T22:49:29
who: btseng[at]mozilla[dot]com
machine: tst-linux64-spot-1420
buildname: b2g_emulator_vm try opt test marionette-webapi
revision: d49d98476104

TEST-UNEXPECTED-ERROR | test_wifi_associate_WPA_EAP_TTLS.js | ScriptTimeoutException: ScriptTimeoutException: timed out
Exception OSError: OSError(2, 'No such file or directory') in <bound method MarionetteTestRunner.cleanup of <__main__.MarionetteTestRunner object at 0x1dd0690>> ignored
Return code: 10

Comment 10

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=try&job_id=6866673
repository: try
start_time: 2015-04-22T21:43:07
who: btseng[at]mozilla[dot]com
machine: tst-linux64-spot-1626
buildname: b2g_emulator_vm try opt test marionette-webapi
revision: 05ecf08f4f5e

TEST-UNEXPECTED-ERROR | test_wifi_associate_WPA_EAP_TTLS.js | ScriptTimeoutException: ScriptTimeoutException: timed out
TEST-UNEXPECTED-ERROR | test_wifi_associate_WPA_EAP_TLS.js | ScriptTimeoutException: ScriptTimeoutException: timed out
Exception OSError: OSError(2, 'No such file or directory') in <bound method MarionetteTestRunner.cleanup of <__main__.MarionetteTestRunner object at 0x1bf2550>> ignored
Return code: 10

Comment 11

[Henry Chang [:hchang]]

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!

Comment 12

[Henry Chang [:hchang]]

Let's see if urandom fixes all the EAP test case failure.

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

Comment 13

[Thomas Zimmermann [:tzimmermann] [:tdz]]

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

[Henry Chang [:hchang]]

(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

[Thomas Zimmermann [:tzimmermann] [:tdz]]

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

[Thomas Zimmermann [:tzimmermann] [:tdz]]

/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

[Henry Chang [:hchang]]

(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

[Kai-Zhen Li [:seinlin][:kli]]

(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

Comment 19

[Edgar Chen [:edgar]]

Pre offline discuss with Henry, let's just disable the failure tests first. I have filed bug 1173697 to track the failure tests.

Comment 20

[Edgar Chen [:edgar]]

Attachment: Patch, v1

Henry, mind reviewing this? Thank you.

Comment 21

[Edgar Chen [:edgar]]

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=75c8329af768&exclusion_profile=false

Comment 22

[Pulsebot]

https://hg.mozilla.org/integration/b2g-inbound/rev/0a965bb6794a

Comment 23

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/0a965bb6794a