Help understanding WPS trace

[Jouni Malinen]

On Fri, Sep 30, 2011 at 10:36:46AM +0100, Dani Camps wrote:
> The, in our opinion, problem is a too high delay between the time when the WPS phase completes and the time when the P2P Client associates to the P2P GO and starts the 4-way key exchange. If you look at the p2p_cli.log, you can see in the following line when the P2P Client starts trying to authenticate for the first time with the P2P GO after WPS completes:
> 
> 1317289042.619717: wlan1: State: DISCONNECTED -> AUTHENTICATING
> 
> 
> Then, the P2P Client only proceeds with the Association and Key exchange 8 seconds later, you can see it in this line.
> 
> 1317289050.672501: wlan1: State: AUTHENTICATING -> ASSOCIATING

There seems to be number of issues on the client side.. It looks like
something is generating unexpected disconnection events and that makes
wpa_supplicant confused. Are you sure there is no other program trying
to control the wireless interface (like Network Manager)?

It is unclear what happens with the first authentication attempt at
1317289042.618844.. It is more or less immediately followed by a
Deauthentication notification at 1317289042.619221 which, I guess, could
be from the previous association. However, it could also be caused by
something else in the system requesting the WLAN card to disconnect at
that point. This results in some apparent confusion in wpa_supplicant
when trying to process the next scan results at 1317289045.666867. This
should have request a new connection, but it assumed that the connection
is already in process from the previous attempt. This costs couple of
seconds and an extra scan.

> This is not something that happens always, many times we observe that the transition between the first Authentication and the Association and Key exchange occurs in around 3 seconds.

This should not really take much time.. The scan operation can take a
few seconds, but it should be possible to optimize that to only use the
expect channel as is done for the WPS provisioning step. I'm not sure
why that did not happen here, though. The unexpected disconnection event
seems to be causing most of the issues here, though. It would be nice to
be able to reproduce this at will to enable some experimentation..

> Digging a bit further the problem seems to be here in the p2p_cli.log:
> 
> 1317289047.619871: wlan1: SME: Authentication timeout
> 1317289047.619879: wpa_driver_nl80211_deauthenticate(addr=00:1b:11:c5:56:a4 reason_code=3)
> 1317289047.619933: nl80211: MLME command failed: ret=-107 (Transport endpoint is not connected)
> 
> For some reason the P2P Client does not proceed with the Reassociation after the first Authentication, then an internal timeout in the P2P Client occurs and the P2P Client cancels its current authentication and so it starts all the process of scanning, authentication and association which results in the mentioned delay. We do not understand why the P2P Client gets hung up after the first Authentication until the timeout occurs. Is this a bug, or is there a reason for the behavior ?

Either something else in the system caused the driver to disconnect or
the timing of the disconnection event after the WPS provisioning step is
perfect for confusing the state between wpa_supplicant and cfg80211.
Anyway, there seems to be a bug somewhere since it should not have taken
that long to recover from the issue.

In addition to the client side issues, there is also one issue on the GO
that adds more delay to the connection. It looks like there is not
enough entropy available for random number generation (is this an
embedded device with no keyboard and mouse?) and that results in the
first 4-way handshake after the WPS provisioning getting rejected while
more entropy is being collected to allow more secure key generation.

> Please let us know if anymore information would be helpful to understand the problem. We can send you the wireshark capture if you think is required.

It could be useful to see what the debug output from mac80211/cfg80211
looks like in dmesg output on the client since the client side issues
seem to be very much related to the association state mismatch and
unexpected processing of disconnection events.

-- 
Jouni Malinen                                            PGP id EFC895FA