Re: ath0, link goes down then up periodically

On Tue, 28 Jun 2005, Eric Masson wrote:
> Hi,
>
> I'm using a Planet WL3560 (atheros chipset) with -current as a DLink
> DWL2000AP client :
>
> Sometimes, ath0 link state goes down then up :
> http://emss.free.fr/informatique/FreeBSD/messages
>
> 80211debug has been set with the following options :
> /usr/local/bin/80211debug +debug +assoc +xrate +power +scan +wme
>
> Any idea ?

   I have observed similar periodic UP/DOWN whilst associating with
certain APs(in my case, DLink DWL-7100AP).  On the other hand, this 
doesn't look like ath specific to me since I can reproduce this
with the same AP + if_wi.

   According to the timestamp, the UP/DOWN interval is *exactly* 1 minute.
I suspect this AP has some sort of "auto-kick-out" function builtin;
that is, if there is no frame from the station within a defined period,
AP will try to re-authenticate with this station(reason 2 - Previous
authentication no longer valid).  In this testing case, I didn't send
any data frame after ath0 associated with the AP.

   If I send something periodically(such like a background ping), the AP
seems happy and no longer kicks me out every single minute.  Notes that
this re-authentication madness doesn't manifest itself on Windows XP
since XP periodically scans all available channels even it has associated
with a BSS.

Jun 29 20:59:46: ath0: received auth from 00:11:22:33:44:55 rssi 61
Jun 29 20:59:46: [00:11:22:33:44:55] recv auth frame with algorithm 0 seq 2
Jun 29 20:59:46: [00:11:22:33:44:55] send assoc_req on channel 9
Jun 29 20:59:46: ath0: received assoc_resp from 00:11:22:33:44:55 rssi 61
Jun 29 20:59:46: [00:11:22:33:44:55] assoc success: long preamble, short slot time
Jun 29 20:59:46: ath0: associated with 00:11:22:33:44:55 ssid "MySSID" channel 9 start 36Mb
Jun 29 20:59:46: ath0: link state changed to UP
Jun 29 21:00:46: ath0: received deauth from 00:11:22:33:44:55 rssi 60
Jun 29 21:00:46: [00:11:22:33:44:55] recv deauthenticate (reason 2)
Jun 29 21:00:46: [00:11:22:33:44:55] send auth on channel 9
Jun 29 21:00:46: ath0: link state changed to DOWN
Jun 29 21:00:46: ath0: received auth from 00:11:22:33:44:55 rssi 59
Jun 29 21:00:46: [00:11:22:33:44:55] recv auth frame with algorithm 0 seq 2
Jun 29 21:00:46: [00:11:22:33:44:55] send assoc_req on channel 9
Jun 29 21:00:46: [00:11:22:33:44:55] discard  duplicate frame, seqno <3939,3939> fragno <0,0> tid 0
Jun 29 21:00:46: ath0: received assoc_resp from 00:11:22:33:44:55 rssi 60
Jun 29 21:00:46: [00:11:22:33:44:55] assoc success: long preamble, short slot time
Jun 29 21:00:46: ath0: associated with 00:11:22:33:44:55 ssid "MySSID" channel 9 start 36Mb
Jun 29 21:00:46: ath0: link state changed to UP
Jun 29 21:01:46: ath0: received deauth from 00:11:22:33:44:55 rssi 60
Jun 29 21:01:46: [00:11:22:33:44:55] recv deauthenticate (reason 2)
Jun 29 21:01:46: [00:11:22:33:44:55] send auth on channel 9
Jun 29 21:01:46: ath0: link state changed to DOWN
Jun 29 21:01:46: ath0: received auth from 00:11:22:33:44:55 rssi 59
Jun 29 21:01:46: [00:11:22:33:44:55] recv auth frame with algorithm 0 seq 2
Jun 29 21:01:46: [00:11:22:33:44:55] send assoc_req on channel 9
Jun 29 21:01:46: ath0: received assoc_resp from 00:11:22:33:44:55 rssi 61
Jun 29 21:01:46: [00:11:22:33:44:55] assoc success: long preamble, short slot time
Jun 29 21:01:46: ath0: associated with 00:11:22:33:44:55 ssid "MySSID" channel 9 start 36Mb
Jun 29 21:01:46: ath0: link state changed to UP
Jun 29 21:02:46: ath0: received deauth from 00:11:22:33:44:55 rssi 60
Jun 29 21:02:46: [00:11:22:33:44:55] recv deauthenticate (reason 2)
Jun 29 21:02:46: [00:11:22:33:44:55] send auth on channel 9
Jun 29 21:02:46: ath0: link state changed to DOWN
Jun 29 21:02:46: ath0: received auth from 00:11:22:33:44:55 rssi 61
Jun 29 21:02:46: [00:11:22:33:44:55] recv auth frame with algorithm 0 seq 2
Jun 29 21:02:46: [00:11:22:33:44:55] send assoc_req on channel 9
Jun 29 21:02:46: ath0: received assoc_resp from 00:11:22:33:44:55 rssi 61
Jun 29 21:02:46: [00:11:22:33:44:55] assoc success: long preamble, short slot time
Jun 29 21:02:46: ath0: associated with 00:11:22:33:44:55 ssid "MySSID" channel 9 start 36Mb
Jun 29 21:02:46: ath0: link state changed to UP
Jun 29 21:03:46: ath0: received deauth from 00:11:22:33:44:55 rssi 61
Jun 29 21:03:46: [00:11:22:33:44:55] recv deauthenticate (reason 2)
Jun 29 21:03:46: [00:11:22:33:44:55] send auth on channel 9
Jun 29 21:03:46: ath0: link state changed to DOWN
Jun 29 21:03:46: ath0: received auth from 00:11:22:33:44:55 rssi 60
Jun 29 21:03:46: [00:11:22:33:44:55] recv auth frame with algorithm 0 seq 2
Jun 29 21:03:46: [00:11:22:33:44:55] send assoc_req on channel 9
Jun 29 21:03:46: ath0: received assoc_resp from 00:11:22:33:44:55 rssi 61
Jun 29 21:03:46: [00:11:22:33:44:55] assoc success: long preamble, short slot time
Jun 29 21:03:46: ath0: associated with 00:11:22:33:44:55 ssid "MySSID" channel 9 start 36Mb
Jun 29 21:03:46: ath0: link state changed to UP
Jun 29 21:04:46: ath0: received deauth from 00:11:22:33:44:55 rssi 61
Jun 29 21:04:46: [00:11:22:33:44:55] recv deauthenticate (reason 2)
Jun 29 21:04:46: [00:11:22:33:44:55] send auth on channel 9
Jun 29 21:04:46: ath0: link state changed to DOWN
Jun 29 21:04:46: ath0: received auth from 00:11:22:33:44:55 rssi 60
Jun 29 21:04:46: [00:11:22:33:44:55] recv auth frame with algorithm 0 seq 2
Jun 29 21:04:46: [00:11:22:33:44:55] send assoc_req on channel 9
Jun 29 21:04:46: ath0: received assoc_resp from 00:11:22:33:44:55 rssi 60
Jun 29 21:04:46: [00:11:22:33:44:55] assoc success: long preamble, short slot time
Jun 29 21:04:46: ath0: associated with 00:11:22:33:44:55 ssid "MySSID" channel 9 start 36Mb
Jun 29 21:04:46: ath0: link state changed to UP
Jun 29 21:05:46: ath0: received deauth from 00:11:22:33:44:55 rssi 60
Jun 29 21:05:46: [00:11:22:33:44:55] recv deauthenticate (reason 2)
Jun 29 21:05:46: [00:11:22:33:44:55] send auth on channel 9
Jun 29 21:05:46: ath0: link state changed to DOWN
Jun 29 21:05:46: ath0: received auth from 00:11:22:33:44:55 rssi 60
Jun 29 21:05:46: [00:11:22:33:44:55] recv auth frame with algorithm 0 seq 2
Jun 29 21:05:46: [00:11:22:33:44:55] send assoc_req on channel 9
Jun 29 21:05:46: ath0: received assoc_resp from 00:11:22:33:44:55 rssi 59
Jun 29 21:05:46: [00:11:22:33:44:55] assoc success: long preamble, short slot time
Jun 29 21:05:46: ath0: associated with 00:11:22:33:44:55 ssid "MySSID" channel 9 start 36Mb
Jun 29 21:05:46: ath0: link state changed to UP
Jun 29 21:06:46: ath0: received deauth from 00:11:22:33:44:55 rssi 60
Jun 29 21:06:46: [00:11:22:33:44:55] recv deauthenticate (reason 2)
Jun 29 21:06:46: [00:11:22:33:44:55] send auth on channel 9
Jun 29 21:06:46: ath0: link state changed to DOWN
Jun 29 21:06:46: ath0: received auth from 00:11:22:33:44:55 rssi 60
Jun 29 21:06:46: [00:11:22:33:44:55] recv auth frame with algorithm 0 seq 2
Jun 29 21:06:46: [00:11:22:33:44:55] send assoc_req on channel 9
Jun 29 21:06:46: [00:11:22:33:44:55] discard  duplicate frame, seqno <3915,3915> fragno <0,0> tid 0
Jun 29 21:06:46: ath0: received assoc_resp from 00:11:22:33:44:55 rssi 59
Jun 29 21:06:46: [00:11:22:33:44:55] assoc success: long preamble, short slot time
Jun 29 21:06:46: ath0: associated with 00:11:22:33:44:55 ssid "MySSID" channel 9 start 36Mb
Jun 29 21:06:46: ath0: link state changed to UP
Jun 29 21:07:46: ath0: received deauth from 00:11:22:33:44:55 rssi 59
Jun 29 21:07:46: [00:11:22:33:44:55] recv deauthenticate (reason 2)
Jun 29 21:07:46: [00:11:22:33:44:55] send auth on channel 9
Jun 29 21:07:46: [00:11:22:33:44:55] discard  duplicate frame, seqno <503,503> fragno <0,0> tid 0
Jun 29 21:07:46: ath0: received auth from 00:11:22:33:44:55 rssi 59
Jun 29 21:07:46: [00:11:22:33:44:55] recv auth frame with algorithm 0 seq 2
Jun 29 21:07:46: [00:11:22:33:44:55] send assoc_req on channel 9
Jun 29 21:07:46: ath0: link state changed to DOWN
Jun 29 21:07:46: ath0: received assoc_resp from 00:11:22:33:44:55 rssi 59
Jun 29 21:07:46: [00:11:22:33:44:55] assoc success: long preamble, short slot time
Jun 29 21:07:46: ath0: associated with 00:11:22:33:44:55 ssid "MySSID" channel 9 start 36Mb
Jun 29 21:07:46: ath0: link state changed to UP
Jun 29 21:08:46: ath0: received deauth from 00:11:22:33:44:55 rssi 59
Jun 29 21:08:46: [00:11:22:33:44:55] recv deauthenticate (reason 2)
Jun 29 21:08:46: [00:11:22:33:44:55] send auth on channel 9
Jun 29 21:08:46: ath0: link state changed to DOWN
Jun 29 21:08:46: ath0: received auth from 00:11:22:33:44:55 rssi 60
Jun 29 21:08:46: [00:11:22:33:44:55] recv auth frame with algorithm 0 seq 2
Jun 29 21:08:46: [00:11:22:33:44:55] send assoc_req on channel 9
Jun 29 21:08:46: ath0: received assoc_resp from 00:11:22:33:44:55 rssi 61
Jun 29 21:08:46: [00:11:22:33:44:55] assoc success: long preamble, short slot time
Jun 29 21:08:46: ath0: associated with 00:11:22:33:44:55 ssid "MySSID" channel 9 start 36Mb
Jun 29 21:08:46: ath0: link state changed to UP
Jun 29 21:09:45: ath0: received deauth from 00:11:22:33:44:55 rssi 61
Jun 29 21:09:45: [00:11:22:33:44:55] recv deauthenticate (reason 2)
Jun 29 21:09:45: [00:11:22:33:44:55] send auth on channel 9
Jun 29 21:09:45: ath0: link state changed to DOWN
Jun 29 21:09:45: ath0: received auth from 00:11:22:33:44:55 rssi 60
Jun 29 21:09:45: [00:11:22:33:44:55] recv auth frame with algorithm 0 seq 2
Jun 29 21:09:45: [00:11:22:33:44:55] send assoc_req on channel 9
Jun 29 21:09:46: ath0: received assoc_resp from 00:11:22:33:44:55 rssi 60
Jun 29 21:09:46: [00:11:22:33:44:55] assoc success: long preamble, short slot time
Jun 29 21:09:46: ath0: associated with 00:11:22:33:44:55 ssid "MySSID" channel 9 start 36Mb
Jun 29 21:09:46: ath0: link state changed to UP