STA can connect, but fails to reconnect within ap_max_inactivity

Tue Feb 3 05:40:09 PST 2009

[this message is from jan 25, i'm resending since the non-member
 moderation does not seem to work, had to subscribe using this
 address too..]

I'm trying to setup a hostap driven AP using a p54usb card; after
some initial problems w/ the driver, now it seems to work.
Except, that the client (a windows mobile device) can not reconnect
within the ap_max_inactivity timeout. ie it successfully associates
and the connection works, but if i turn off the device (wifi part)
and then turn it on again the connection reliably fails. If i wait
until ap_max_inactivity seconds passes, the connection succeeds.

Log below, corresponds to one successful connection attempt, then
switching off wifi, followed by the failed reconnection, then ^C.

Could this be some kind of hostapd misconfiguration?
The diff vs the default hostapd,conf is below; the problem appears
both when using WPA and WPA2, haven't tried anything else.

hostap from git, as of a few days ago.

artur

[conf:]

+driver=nl80211
-interface=wlan0
+interface=ap0
+driver=nl80211
-ssid=test
+ssid=[...]
+country_code=[...]
+ieee80211d=1
-hw_mode=a
+hw_mode=g
-channel=60
+channel=6
-rts_threshold=2347
-fragm_threshold=2346
+preamble=1
-auth_algs=3
+auth_algs=1
+ap_max_inactivity=300
+ieee8021x=1
-eap_server=0
+eap_server=1
+wpa=2
+wpa_passphrase=[...]
+wpa_key_mgmt=WPA-PSK
+wpa_pairwise=CCMP
+rsn_pairwise=CCMP
+wpa_strict_rekey=1
+peerkey=0

[log:]

ctrl_interface_group=0
Opening raw packet socket for ifindex -1212088056
BSS count 1, BSSID mask ff:ff:ff:ff:ff:ff (0 bits)
Failed to set country code
SIOCGIWRANGE: WE(compiled)=22 WE(source)=21 enc_capa=0xf
nl80211: Added 802.11b mode based on 802.11g information
Allowed channel: mode=1 chan=1 freq=2412 MHz max_tx_power=27 dBm
Allowed channel: mode=1 chan=2 freq=2417 MHz max_tx_power=27 dBm
Allowed channel: mode=1 chan=3 freq=2422 MHz max_tx_power=27 dBm
Allowed channel: mode=1 chan=4 freq=2427 MHz max_tx_power=27 dBm
Allowed channel: mode=1 chan=5 freq=2432 MHz max_tx_power=27 dBm
Allowed channel: mode=1 chan=6 freq=2437 MHz max_tx_power=27 dBm
Allowed channel: mode=1 chan=7 freq=2442 MHz max_tx_power=27 dBm
Allowed channel: mode=1 chan=8 freq=2447 MHz max_tx_power=27 dBm
Allowed channel: mode=1 chan=9 freq=2452 MHz max_tx_power=27 dBm
Allowed channel: mode=1 chan=10 freq=2457 MHz max_tx_power=27 dBm
Allowed channel: mode=1 chan=11 freq=2462 MHz max_tx_power=27 dBm
Allowed channel: mode=0 chan=1 freq=2412 MHz max_tx_power=27 dBm
Allowed channel: mode=0 chan=2 freq=2417 MHz max_tx_power=27 dBm
Allowed channel: mode=0 chan=3 freq=2422 MHz max_tx_power=27 dBm
Allowed channel: mode=0 chan=4 freq=2427 MHz max_tx_power=27 dBm
Allowed channel: mode=0 chan=5 freq=2432 MHz max_tx_power=27 dBm
Allowed channel: mode=0 chan=6 freq=2437 MHz max_tx_power=27 dBm
Allowed channel: mode=0 chan=7 freq=2442 MHz max_tx_power=27 dBm
Allowed channel: mode=0 chan=8 freq=2447 MHz max_tx_power=27 dBm
Allowed channel: mode=0 chan=9 freq=2452 MHz max_tx_power=27 dBm
Allowed channel: mode=0 chan=10 freq=2457 MHz max_tx_power=27 dBm
Allowed channel: mode=0 chan=11 freq=2462 MHz max_tx_power=27 dBm
RATE[0] rate=10 flags=0x6
RATE[1] rate=20 flags=0x6
RATE[2] rate=55 flags=0x6
RATE[3] rate=110 flags=0x6
RATE[4] rate=60 flags=0x0
RATE[5] rate=90 flags=0x0
RATE[6] rate=120 flags=0x0
RATE[7] rate=180 flags=0x0
RATE[8] rate=240 flags=0x0
RATE[9] rate=360 flags=0x0
RATE[10] rate=480 flags=0x0
RATE[11] rate=540 flags=0x0
Passive scanning not supported
Flushing old station entries
Deauthenticate all stations
Mode: IEEE 802.11g  Channel: 6  Frequency: 2437 MHz
Using interface ap0 with hwaddr 00:00:00:00:00:e6 and ssid '[...]'
SSID - hexdump_ascii(len=3):
[...]
PSK (ASCII passphrase) - hexdump_ascii(len=8):
[...]
PSK (from passphrase) - hexdump(len=32): [...]
WPA: group state machine entering state GTK_INIT (VLAN-ID 0)
GMK - hexdump(len=32): [REMOVED]
GTK - hexdump(len=16): [REMOVED]
WPA: group state machine entering state SETKEYSDONE (VLAN-ID 0)
ap0: Setup of interface done.
MGMT (TX callback) ACK
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) fail
mgmt::proberesp cb
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) fail
mgmt::proberesp cb
MGMT (TX callback) fail
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) fail
mgmt::proberesp cb
MGMT (TX callback) fail
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) fail
mgmt::proberesp cb
MGMT (TX callback) fail
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) fail
mgmt::proberesp cb
MGMT (TX callback) fail
mgmt::proberesp cb
MGMT
mgmt::auth
authentication: STA=00:00:00:00:00:76 auth_alg=0 auth_transaction=1 status_code=0 wep=0
  New STA
ap0: STA 00:00:00:00:00:76 IEEE 802.11: authentication OK (open system)
ap0: STA 00:00:00:00:00:76 MLME: MLME-AUTHENTICATE.indication(00:00:00:00:00:76, OPEN_SYSTEM)
ap0: STA 00:00:00:00:00:76 MLME: MLME-DELETEKEYS.request(00:00:00:00:00:76)
authentication reply: STA=00:00:00:00:00:76 auth_alg=0 auth_transaction=2 resp=0 (IE len=0)
MGMT (TX callback) ACK
mgmt::auth cb
ap0: STA 00:00:00:00:00:76 IEEE 802.11: authenticated
MGMT
mgmt::assoc_req
association request: STA=00:00:00:00:00:76 capab_info=0x431 listen_interval=3
WME IE - hexdump(len=7): 00 50 f2 02 00 01 00
Validating WME IE: OUI 00:50:f2  OUI type 2  OUI sub-type 0  version 1
  new AID 1
ap0: STA 00:00:00:00:00:76 IEEE 802.11: association OK (aid 1)
MGMT (TX callback) ACK
mgmt::assoc_resp cb
ap0: STA 00:00:00:00:00:76 IEEE 802.11: associated (aid 1)
ap0: STA 00:00:00:00:00:76 MLME: MLME-ASSOCIATE.indication(00:00:00:00:00:76)
ap0: STA 00:00:00:00:00:76 MLME: MLME-DELETEKEYS.request(00:00:00:00:00:76)
ap0: STA 00:00:00:00:00:76 WPA: event 1 notification
ap0: STA 00:00:00:00:00:76 WPA: start authentication
WPA: 00:00:00:00:00:76 WPA_PTK entering state INITIALIZE
ap0: STA 00:00:00:00:00:76 IEEE 802.1X: unauthorizing port
WPA: 00:00:00:00:00:76 WPA_PTK_GROUP entering state IDLE
WPA: 00:00:00:00:00:76 WPA_PTK entering state AUTHENTICATION
WPA: 00:00:00:00:00:76 WPA_PTK entering state AUTHENTICATION2
WPA: 00:00:00:00:00:76 WPA_PTK entering state INITPSK
WPA: 00:00:00:00:00:76 WPA_PTK entering state PTKSTART
ap0: STA 00:00:00:00:00:76 WPA: sending 1/4 msg of 4-Way Handshake
WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=8 kde_len=0 keyidx=0 encr=0)
IEEE 802.1X: 121 bytes from 00:00:00:00:00:76
   IEEE 802.1X: version=1 type=3 length=117
ap0: STA 00:00:00:00:00:76 WPA: received EAPOL-Key frame (2/4 Pairwise)
WPA: 00:00:00:00:00:76 WPA_PTK entering state PTKCALCNEGOTIATING
WPA: PTK derivation - A1=00:00:00:00:00:e6 A2=00:00:00:00:00:76
WPA: PMK - hexdump(len=32): [REMOVED]
WPA: PTK - hexdump(len=64): [REMOVED]
WPA: 00:00:00:00:00:76 WPA_PTK entering state PTKCALCNEGOTIATING2
WPA: 00:00:00:00:00:76 WPA_PTK entering state PTKINITNEGOTIATING
ap0: STA 00:00:00:00:00:76 WPA: sending 3/4 msg of 4-Way Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=1 pairwise=8 kde_len=46 keyidx=1 encr=1)
Plaintext EAPOL-Key Key Data - hexdump(len=56): [REMOVED]
ap0: STA 00:00:00:00:00:76 WPA: EAPOL-Key timeout
WPA: 00:00:00:00:00:76 WPA_PTK entering state PTKINITNEGOTIATING
ap0: STA 00:00:00:00:00:76 WPA: sending 3/4 msg of 4-Way Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=1 pairwise=8 kde_len=46 keyidx=1 encr=1)
Plaintext EAPOL-Key Key Data - hexdump(len=56): [REMOVED]
IEEE 802.1X: 99 bytes from 00:00:00:00:00:76
   IEEE 802.1X: version=1 type=3 length=95
ap0: STA 00:00:00:00:00:76 WPA: received EAPOL-Key frame (4/4 Pairwise)
WPA: 00:00:00:00:00:76 WPA_PTK entering state PTKINITDONE
ap0: STA 00:00:00:00:00:76 IEEE 802.1X: authorizing port
ap0: STA 00:00:00:00:00:76 RADIUS: starting accounting session 497C453B-00000000
ap0: STA 00:00:00:00:00:76 WPA: pairwise key handshake completed (RSN)
IEEE 802.1X: 99 bytes from 00:00:00:00:00:76
   IEEE 802.1X: version=1 type=3 length=95
ap0: STA 00:00:00:00:00:76 WPA: received EAPOL-Key 4/4 Pairwise with unexpected replay counter
received replay counter - hexdump(len=8): 00 00 00 00 00 00 00 03
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT
mgmt::auth
authentication: STA=00:00:00:00:00:76 auth_alg=0 auth_transaction=1 status_code=0 wep=0
ap0: STA 00:00:00:00:00:76 IEEE 802.11: authentication OK (open system)
ap0: STA 00:00:00:00:00:76 WPA: event 0 notification
ap0: STA 00:00:00:00:00:76 MLME: MLME-AUTHENTICATE.indication(00:00:00:00:00:76, OPEN_SYSTEM)
ap0: STA 00:00:00:00:00:76 MLME: MLME-DELETEKEYS.request(00:00:00:00:00:76)
authentication reply: STA=00:00:00:00:00:76 auth_alg=0 auth_transaction=2 resp=0 (IE len=0)
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT (TX callback) ACK
mgmt::proberesp cb
MGMT (TX callback) ACK
mgmt::proberesp cb
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
STA 00:00:00:00:00:76 sent probe request for broadcast SSID
MGMT
mgmt::auth
authentication: STA=00:00:00:00:00:76 auth_alg=0 auth_transaction=1 status_code=0 wep=0
ap0: STA 00:00:00:00:00:76 IEEE 802.11: authentication OK (open system)
ap0: STA 00:00:00:00:00:76 WPA: event 0 notification
ap0: STA 00:00:00:00:00:76 MLME: MLME-AUTHENTICATE.indication(00:00:00:00:00:76, OPEN_SYSTEM)
ap0: STA 00:00:00:00:00:76 MLME: MLME-DELETEKEYS.request(00:00:00:00:00:76)
authentication reply: STA=00:00:00:00:00:76 auth_alg=0 auth_transaction=2 resp=0 (IE len=0)
[killed hostapd]
Signal 15 received - terminating
ap0: STA 00:00:00:00:00:76 MLME: MLME-DEAUTHENTICATE.indication(00:00:00:00:00:76, 1)
ap0: STA 00:00:00:00:00:76 MLME: MLME-DELETEKEYS.request(00:00:00:00:00:76)
Removing station 00:00:00:00:00:76
ap0: STA 00:00:00:00:00:76 WPA: strict rekeying - force GTK rekey since STA is leaving
Flushing old station entries
Deauthenticate all stations