Re: wpa_supplicant AP scanning doesn't work after first association

On Sun, 11 Sep 2005 14:36:42 +1000
Sam Lawrance <boris_at_brooknet.com.au> wrote:

> On Sat, 2005-09-10 at 10:55 -0700, Brooks Davis wrote:
> > On Sat, Sep 10, 2005 at 11:50:50PM +1000, Sam Lawrance wrote:
> > > Hi,
> > > 
> > > The station boots up and associates with the AP OK.  This works
> > > great for days.  If I power down the AP and power it up again,
> > > after disassociating, wpa_supplicant fails to locate the access
> > > point in its scans.
> > > 
> > > I am using RELENG_6 from 3 September.
> > > 
> > > The station is a D-Link DWL-G510 (atheros based)
> > > ath0_at_pci0:8:0:  class=0x020000 card=0x3a161186 chip=0x001a168c
> > > rev=0x01 hdr=0x00.
> > > 
> > > rc.conf entry:
> > > ifconfig_ath0="WPA inet 192.168.0.1 netmask 255.255.255.0"
> > > 
> > > wpa_supplicant.conf contains:
> > > ctrl_interface=/var/run/wpa_supplicant
> > > ctrl_interface_group=wheel
> > > network={
> > >         ssid="sunset"
> > >         scan_ssid=1
> > >         key_mgmt=WPA-PSK
> > > 	psk= ... etc etc ...
> > > }
> > > 
> > > The access point is a D-Link DI-524 firmware v2.02, configured for
> > > WPA-PSK
> > > 
> > > Output from wpa_supplicant:
> > > 
> > > Starting AP scan (specific SSID)
> > > Scan SSID - hexdump_ascii(len=6):
> > >      73 75 6e 73 65 74
> > > sunset Received 0 bytes of scan results (1 BSSes)
> > > Scan results: 1
> > > Selecting BSS from priority group 0
> > > 0: 00:0f:3d:29:79:f5 ssid='sunset' wpa_ie_len=24 rsn_ie_len=0
> > >    selected
> > > Trying to associate with 00:0f:3d:29:79:f5 (SSID='sunset'
> > > freq=2437 MHz) Cancelling scan request
> > > Automatic auth_alg selection: 0x1
> > > WPA: using IEEE 802.11i/D3.0
> > > WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2
> > > WPA: using GTK TKIP
> > > WPA: using PTK TKIP
> > > WPA: using KEY_MGMT WPA-PSK WPA: Own WPA IE - hexdump(len=24): dd
> > > 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2
> > > 02 No keys have been configured - skip key clearing
> > > wpa_driver_bsd_set_drop_unencrypted: enabled=1
> > > wpa_driver_bsd_associate: ssid 'sunset' wpa ie len 24 pairwise 2
> > > group 2 key mgmt 1 wpa_driver_bsd_associate: set PRIVACY 1
> > > Setting authentication timeout: 5 sec 0 usec Association event -
> > > clear replay counter Associated to a new BSS:
> > > BSSID=00:0f:3d:29:79:f5 No keys have been configured - skip key
> > > clearing Associated with 00:0f:3d:29:79:f5
> > > Setting authentication timeout: 10 sec 0 usec
> > > RX EAPOL from 00:0f:3d:29:79:f5 
> > > 
> > > ... power down AP, wait a minute, power up AP  ...
> > > 
> > > Starting AP scan (broadcast SSID)
> > > Received 0 bytes of scan results (0 BSSes)
> > > Scan results: 0
> > > Selecting BSS from priority group 0
> > > No suitable AP found.
> > > Setting scan request: 5 sec 0 usec
> > > Starting AP scan (specific SSID)
> > > Scan SSID - hexdump_ascii(len=6):
> > >      73 75 6e 73 65 74
> > > sunset Received 0 bytes of scan results (0 BSSes)
> > > Scan results: 0
> > > Selecting BSS from priority group 0
> > > No suitable AP found.
> > > 
> > > 
> > > Please let me know what other information I can collect to help
> > > figure this out.  I hope it's not pilot error :)
> > 
> > Running current as of August 23rd an connecting using WPA-PSK to
> > connect to a DI-524 running firmware 1.11, I reconnect promptly
> > when I power the AP back on.
> 
> This DI-524 is a revision B.  Anyhow, I'm going to turn on some ath
> debugging output and see if it lends any clues.

It seems that the AP is responding to the scans.  However,
wpa_supplicant continues to report finding no APs.

ath_chan_set: 5 (2432 MHz) -> 6 (2437 MHz)
ath_draintxq: beacon queue 0
ath_tx_stopdma: tx queue [0] 0, link 0
ath_tx_stopdma: tx queue [1] 0x1ec45e00, link 0
ath_tx_stopdma: tx queue [2] 0, link 0
ath_tx_stopdma: tx queue [3] 0, link 0
ath_tx_stopdma: tx queue [8] 0, link 0
ath_stoprecv: rx queue 0x1c18b0, link 0xc1a4d884
ath_mode_init: RX filter 0x17, MC filter 00100021:00301040
ath_rate_update: set xmit rate for 00:0f:3d:29:79:f5 to 1M
ath_tx_start: m 0xc1b86800 len 76
NODS 00:11:95:e5:45:c3->ff:ff:ff:ff:ff:ff(ff:ff:ff:ff:ff:ff) probe_req 1M
4000 0000 ffff ffff ffff 0011 95e5 45c3 ffff ffff ffff 2005 0006 7375 6e73 6574 0108 0204 0b16 0c12 1824 3204 3048 606c dd16 0050 f201 0100 0050 f202 0100 0050 f202 0100 0050 f202
ath_tx_start: 0: 00000000 1e73a898 2124004c 01000048 000b0000 0000001b
ath_tx_start: TXDP[1] = 0x1ec46bc0 (0xd5b10bc0) depth 1
ath_start: ignore data packet, state 1
Sep 13 17:23:18 dirk last message repeated 2 times
R0 (0xc1a4d8b0 0x1c18b0) 001c18dc 173f9800 00000000 00000800 134d805e 2bb60003 *
NODS 00:0f:3d:29:79:f5->00:11:95:e5:45:c3(00:0f:3d:29:79:f5) probe_resp 1M +52
5000 9800 0011 95e5 45c3 000f 3d29 79f5 000f 3d29 79f5 7004 45da 4e00 0000 0000 6400 3104 0006 7375 6e73 6574 0104 8284 8b96 0301 062a 0100 3208 0c12 1824 3048 606c dd16 0050 f201 0100 0050 f202 0100 0050 f202 0100 0050 f202 43fd f3dc

I'll continue poking around.