Modify

Opened 7 years ago

Closed 7 years ago

Last modified 4 years ago

#8830 closed defect (fixed)

WNDR3700 & Intel clients routinely deauthenticate from AP

Reported by: got_milk <ryan.morrison04@…> Owned by: developers
Priority: high Milestone: Barrier Breaker 14.07
Component: base system Version: Trunk
Keywords: Cc:

Description

Hardware: Windows 7 x64, Intel WiFi Link 5300 AGN
Netgear WNDR3700, Trunk r25428

Description: Intel client connected to AP routinely deauthenticates "due to local deauth request", forcing the client to renegotiate the connection to the AP. This causes connection disruptions and makes VoIP, gaming and other latency dependent applications unusable. Corresponding message in system log:

Feb  9 21:41:58 WNDR3700 daemon.info hostapd: wlan1: STA 00:21:[snip] IEEE 802.11: deauthenticated due to local deauth request

Feb  9 21:41:58 WNDR3700 daemon.info hostapd: wlan1: STA 00:21:[snip] IEEE 802.11: authenticated

Feb  9 21:41:58 WNDR3700 daemon.info hostapd: wlan1: STA 00:21:[snip] IEEE 802.11: associated (aid 1)

Feb  9 21:41:58 WNDR3700 daemon.info hostapd: wlan1: STA 00:21:[snip] WPA: pairwise key handshake completed (RSN)

Expected result: Client connects to AP and connection is maintained.

Result: Client connects to AP but is deauthenticated and renegotiates the connection.

Other Information: Contents of /etc/config/wireless:

config 'wifi-device' 'radio0'
        option 'type' 'mac80211'
        option 'macaddr' '30:46:[snip]'
        option 'hwmode' '11ng'
        option 'htmode' 'HT20'
        list 'ht_capab' 'SHORT-GI-40'
        list 'ht_capab' 'TX-STBC'
        list 'ht_capab' 'RX-STBC1'
        list 'ht_capab' 'DSSS_CCK-40'
        option 'disabled' '0'
        option 'channel' '1'
        option 'txpower' '20'
        option 'country' 'CA'

config 'wifi-iface'
        option 'device' 'radio0'
        option 'network' 'lan'
        option 'mode' 'ap'
        option 'ssid' '[snip]'
        option 'encryption' 'psk2'
        option 'key' '[snip]'

config 'wifi-device' 'radio1'
        option 'type' 'mac80211'
        option 'macaddr' '30:46:[snip]'
        option 'hwmode' '11na'
        list 'ht_capab' 'SHORT-GI-40'
        list 'ht_capab' 'TX-STBC'
        list 'ht_capab' 'RX-STBC1'
        list 'ht_capab' 'DSSS_CCK-40'
        option 'disabled' '0'
        option 'country' 'CA'
        option 'channel' '153'
        option 'htmode' 'HT40-'
        option 'txpower' '20'

config 'wifi-iface'
        option 'device' 'radio1'
        option 'network' 'lan'
        option 'mode' 'ap'
        option 'ssid' '[snip]'
        option 'encryption' 'psk2'
        option 'key' '[snip]'

Attachments (0)

Change History (87)

comment:1 Changed 7 years ago by nbd

Does this happen with HT20 as well? Also, please try latest trunk, it contains some AP mode fixes for aggregation behavior when the client enters powersave mode.

comment:2 Changed 7 years ago by got_milk <ryan.morrison04@…>

Yes, this occurs on HT20 as well. I am currently building r25453 and will upgrade and test when complete.

comment:3 Changed 7 years ago by got_milk <ryan.morrison04@…>

Update: Upgraded to r25453, issue is still occurring.

Feb 10 18:29:22 WNDR3700 daemon.info hostapd: wlan1: STA 00:21:[snip] WPA: group key handshake completed (RSN)
Feb 10 18:29:22 WNDR3700 daemon.info hostapd: wlan1: STA 00:21:[snip] WPA: received EAPOL-Key 2/2 Group with unexpected replay counter
Feb 10 18:29:22 WNDR3700 daemon.info hostapd: wlan1: STA 00:21:[snip] WPA: received EAPOL-Key 2/2 Group with unexpected replay counter
Feb 10 18:39:24 WNDR3700 daemon.info hostapd: wlan1: STA 00:21:[snip] IEEE 802.11: deauthenticated due to local deauth request
Feb 10 18:39:24 WNDR3700 daemon.info hostapd: wlan1: STA 00:21:[snip] IEEE 802.11: authenticated
Feb 10 18:39:24 WNDR3700 daemon.info hostapd: wlan1: STA 00:21:[snip] IEEE 802.11: associated (aid 1)
Feb 10 18:39:24 WNDR3700 daemon.info hostapd: wlan1: STA 00:21:[snip] WPA: pairwise key handshake completed (RSN)

I am also seeing large amounts of "lag" spikes occurring with no corresponding log entries every 3-5 minutes.

comment:4 follow-up: Changed 7 years ago by codyrocco

confirmed also on intel 6300 , windows xp 32bit

comment:5 in reply to: ↑ 4 Changed 7 years ago by Alex

And on 4965.

Please provide a debug level we should use for useful messages (the "deauthenticated due to local deauth request - authenticated - associated" symptom is very old).

  1 21:40:09 OpenWrt user.info hostapd: wlan0: STA 00:1d:73:c9:07:d1 WPA: group key handshake completed (RSN)
Feb  1 21:40:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: deauthenticated due to local deauth request
Feb  1 21:40:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: authenticated
Feb  1 21:40:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: associated (aid 2)
Feb  1 21:40:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 WPA: pairwise key handshake completed (RSN)
Feb  1 21:50:09 OpenWrt user.info hostapd: wlan0: STA 00:1d:73:c9:07:d1 WPA: group key handshake completed (RSN)
Feb  1 21:50:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: deauthenticated due to local deauth request
Feb  1 21:50:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: authenticated
Feb  1 21:50:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: associated (aid 2)
Feb  1 21:50:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 WPA: pairwise key handshake completed (RSN)
Feb  1 22:00:09 OpenWrt user.info hostapd: wlan0: STA 00:1d:73:c9:07:d1 WPA: group key handshake completed (RSN)
Feb  1 22:00:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: deauthenticated due to local deauth request
Feb  1 22:00:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: authenticated
Feb  1 22:00:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: associated (aid 2)
Feb  1 22:00:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 WPA: pairwise key handshake completed (RSN)
Feb  1 22:10:09 OpenWrt user.info hostapd: wlan0: STA 00:1d:73:c9:07:d1 WPA: group key handshake completed (RSN)
Feb  1 22:10:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: deauthenticated due to local deauth request
Feb  1 22:10:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: authenticated
Feb  1 22:10:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: associated (aid 2)
Feb  1 22:10:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 WPA: pairwise key handshake completed (RSN)
Feb  1 22:12:33 OpenWrt user.info hostapd: wlan0: STA 00:25:d3:20:02:37 IEEE 802.11: authenticated
Feb  1 22:12:33 OpenWrt user.info hostapd: wlan0: STA 00:25:d3:20:02:37 IEEE 802.11: associated (aid 3)
Feb  1 22:12:33 OpenWrt user.info hostapd: wlan0: STA 00:25:d3:20:02:37 WPA: pairwise key handshake completed (RSN)
Feb  1 22:20:09 OpenWrt user.info hostapd: wlan0: STA 00:25:d3:20:02:37 WPA: group key handshake completed (RSN)
Feb  1 22:20:09 OpenWrt user.info hostapd: wlan0: STA 00:1d:73:c9:07:d1 WPA: group key handshake completed (RSN)
Feb  1 22:20:12 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: deauthenticated due to local deauth request
Feb  1 22:20:13 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: authenticated
Feb  1 22:20:13 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 IEEE 802.11: associated (aid 2)
Feb  1 22:20:13 OpenWrt user.info hostapd: wlan0: STA 00:1f:3b:36:5e:67 WPA: pairwise key handshake completed (RSN)

And I think it's only a consequence of the error, because the "dropouts" or better described the lag occurs in much smaller intervals:

64 bytes from 192.168.0.112: seq=0 ttl=128 time=127.387 ms
64 bytes from 192.168.0.112: seq=1 ttl=128 time=57.166 ms
64 bytes from 192.168.0.112: seq=2 ttl=128 time=5071.830 ms
64 bytes from 192.168.0.112: seq=3 ttl=128 time=4088.253 ms
64 bytes from 192.168.0.112: seq=4 ttl=128 time=3089.199 ms
64 bytes from 192.168.0.112: seq=5 ttl=128 time=2092.010 ms
64 bytes from 192.168.0.112: seq=6 ttl=128 time=1092.582 ms
64 bytes from 192.168.0.112: seq=7 ttl=128 time=93.835 ms
64 bytes from 192.168.0.112: seq=8 ttl=128 time=41.079 ms
64 bytes from 192.168.0.112: seq=9 ttl=128 time=55.435 ms
64 bytes from 192.168.0.112: seq=10 ttl=128 time=81.754 ms
64 bytes from 192.168.0.112: seq=11 ttl=128 time=4186.433 ms
64 bytes from 192.168.0.112: seq=12 ttl=128 time=3187.405 ms
64 bytes from 192.168.0.112: seq=13 ttl=128 time=2188.532 ms
64 bytes from 192.168.0.112: seq=14 ttl=128 time=1190.606 ms
64 bytes from 192.168.0.112: seq=15 ttl=128 time=192.245 ms
64 bytes from 192.168.0.112: seq=16 ttl=128 time=41.548 ms
64 bytes from 192.168.0.112: seq=17 ttl=128 time=90.404 ms
64 bytes from 192.168.0.112: seq=18 ttl=128 time=73.092 ms
64 bytes from 192.168.0.112: seq=19 ttl=128 time=4275.571 ms
64 bytes from 192.168.0.112: seq=20 ttl=128 time=3276.626 ms
64 bytes from 192.168.0.112: seq=21 ttl=128 time=2281.039 ms
64 bytes from 192.168.0.112: seq=22 ttl=128 time=1280.984 ms
64 bytes from 192.168.0.112: seq=23 ttl=128 time=282.641 ms
64 bytes from 192.168.0.112: seq=24 ttl=128 time=37.204 ms
64 bytes from 192.168.0.112: seq=25 ttl=128 time=57.981 ms
64 bytes from 192.168.0.112: seq=26 ttl=128 time=86.139 ms
64 bytes from 192.168.0.112: seq=27 ttl=128 time=4361.613 ms
64 bytes from 192.168.0.112: seq=28 ttl=128 time=3363.509 ms
64 bytes from 192.168.0.112: seq=29 ttl=128 time=2364.671 ms
64 bytes from 192.168.0.112: seq=30 ttl=128 time=1364.611 ms
64 bytes from 192.168.0.112: seq=31 ttl=128 time=368.826 ms
64 bytes from 192.168.0.112: seq=32 ttl=128 time=40.593 ms
64 bytes from 192.168.0.112: seq=33 ttl=128 time=57.585 ms
64 bytes from 192.168.0.112: seq=34 ttl=128 time=79.283 ms

Propably unrelated, but I noted that simultanous transfers in both directions is hindering the communication very excessive.

(And the situation is even worse on Vista then on XP)

Replying to codyrocco:

confirmed also on intel 6300 , windows xp 32bit

comment:6 Changed 7 years ago by Elphidium

Confirmed on a RSPro + R52HN and intel 6200. gcc 4.5.1+l kernel 2.6.37. r25443. ht20.

Feb 11 13:17:09 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:09 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:09 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:13 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:13 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:13 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:15 rspro daemon.info hostapd: wlan0: STA 00:24:2b:cd:bd:d9 IEEE 802.11: disassociated
Feb 11 13:17:17 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:17 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:17 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:19 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:19 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:19 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:21 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:21 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:21 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:26 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:26 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:26 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:28 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:28 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:28 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:29 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:29 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:29 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:31 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:31 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:31 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:34 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:34 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:34 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:40 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:40 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:40 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:43 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:43 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:43 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:44 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:44 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:44 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:47 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:47 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:47 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:47 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: received EAPOL-Key 2/4 Pairwise with unexpected replay counter
Feb 11 13:17:47 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:49 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:49 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:49 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:51 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:51 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:51 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:17:54 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:17:54 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:17:54 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:01 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:01 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:01 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:04 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:04 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:04 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:08 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:08 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:08 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:09 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:09 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:09 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:11 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:11 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:11 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:14 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:14 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:14 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:20 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:20 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:20 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:21 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:21 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:21 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:23 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:23 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:23 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:24 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:24 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:24 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:29 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:29 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:29 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:35 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:35 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:35 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:38 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:38 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:38 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:44 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:44 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:44 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:49 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:49 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:49 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:52 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:52 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:52 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:18:56 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:18:56 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:18:56 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)
Feb 11 13:26:24 rspro daemon.info hostapd: wlan0: STA 00:1b:63:08:7e:d6 WPA: group key handshake completed (RSN)
Feb 11 13:26:24 rspro daemon.info hostapd: wlan0: STA 00:13:33:80:ee:ec WPA: group key handshake completed (RSN)
Feb 11 13:26:24 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: group key handshake completed (RSN)
Feb 11 13:36:24 rspro daemon.info hostapd: wlan0: STA 00:1b:63:08:7e:d6 WPA: group key handshake completed (RSN)
Feb 11 13:36:24 rspro daemon.info hostapd: wlan0: STA 00:13:33:80:ee:ec WPA: group key handshake completed (RSN)
Feb 11 13:36:27 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: deauthenticated due to local deauth request
Feb 11 13:36:27 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: authenticated
Feb 11 13:36:27 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 IEEE 802.11: associated (aid 2)
Feb 11 13:36:27 rspro daemon.info hostapd: wlan0: STA 00:27:10:c4:54:b4 WPA: pairwise key handshake completed (RSN)

comment:7 Changed 7 years ago by got_milk <ryan.morrison04@…>

As a follow-up, I'm working around the issue for now by using an old router converted into a wireless bridge using DD-WRT. The latency spikes and lag have disappeared completely and there are no more deauthentications due to local requests appearing in the log.

This occurs with the latest Intel 14.x.x.x driver series and I can also reproduce on the 13.x.x.x driver series as well.

comment:8 Changed 7 years ago by anonymous

Same here, but not only Intel chipsets/clients are affected by disconnects/deauthentication (a Intel Wifi client is among others clients). Disconnects happens quite often (after one or two days of uptime). A reconnect is not possible so I have to restart the router (or using "wifi" command).

Wonder why there are not more complaints.

Router is a Asus WL500gP with TL-WN861N (ath9k) miniPCI card running r25443.

comment:9 Changed 7 years ago by Craig <candrews@…>

Intel has acknowledged a firmware bug in their wireless chipsets - perhaps that is the problem being experienced here? https://bugzilla.kernel.org/show_bug.cgi?id=16691

comment:10 Changed 7 years ago by got_milk <ryan.morrison04@…>

That only applies to Linux clients. The Linux driver and Windows driver are two very separate entities.

comment:11 Changed 7 years ago by Elphidium

I confirm the bug with a macbook client , atheros airport, not so often than intel, but occurs.

comment:12 Changed 7 years ago by Alex

I thought I'm stable with r25261.

But it turned out otherwise, after I've started an l2tp tunnel over the wireless connection. As the stability test was running for hours without problems before, that doesn't seem like a pure accident.

But in my opinion really important to mention is that the high latencies are independent from the "deauthenticated due to local deauth request - authenticated - associated" log entries in my case.
Because they are there even before the latency rises.

What was new in my case this time is the following:

Jan  3 11:00:54 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d9efc pending frames: 1 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:00:55 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d9efc pending frames: 4 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:00:56 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d9efc pending frames: 7 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:00:57 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d9efc pending frames: 13 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:00:58 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d9efc pending frames: 17 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:00:59 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d9efc pending frames: 22 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:01:00 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d9efc pending frames: 25 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:07:48 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d8084 pending frames: 31 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:07:49 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d8084 pending frames: 40 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:07:50 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d8084 pending frames: 41 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:07:51 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d8084 pending frames: 42 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:07:52 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d8084 pending frames: 43 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:07:53 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d8084 pending frames: 43 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:07:54 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d8084 pending frames: 54 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.
Jan  3 11:07:55 OpenWrt kern.err kernel: ath: txq: 831e179c axq_qnum: 2, mac80211_qnum: 2 axq_link: a31d8084 pending frames: 57 axq_acq empty: 0 stopped: 0 axq_depth: 0  Attempting to restart tx logic.

comment:13 Changed 7 years ago by got_milk <ryan.morrison04@…>

Putting a bump on this - a solution is desperately needed here. I can't VPN or SSH over wireless as it lags every couple of minutes or so.

comment:14 Changed 7 years ago by jeyjay

some simple question: are you running collectd or luci-app-statistics? Can someone try to remove it and see if things are getting better?

comment:15 Changed 7 years ago by got_milk <ryan.morrison04@…>

Rebuilt with VnStat instead of collectd, no difference, still getting latency issues every couple of minutes.

comment:16 Changed 7 years ago by jeyjay

to understand things right:

Are you only affected by spikes of lag or do you also experience frequent disconnects of the Wifi/Wlan connection?

I'm affected by both problems.

Regarding the second point a possible solution is to remove collectd (see #8707).

Cheers

comment:17 Changed 7 years ago by got_milk <ryan.morrison04@…>

I don't have any disconnects - only spikes of latency.

I removed both collectd and luci-app-statistics and replaced it with VnStat and the issue persists.

comment:18 Changed 7 years ago by got_milk <ryan.morrison04@…>

Updated to r25575, issue still persists.

If any developers are interested I have ping logs showing the latency occur + a Wireshark capture from the affected machine.

comment:19 Changed 7 years ago by got_milk <ryan.morrison04@…>

An update:

This problem is very prominent on OpenWrt trunk r25575.

DD-WRT SVN r16214 also has this issue, however, the latency spikes are not nearly as dramatic as on OpenWrt and rarely cause connection loss (as OpenWrt routinely did).

Netgear stock firmware v1.0.7.98 does NOT suffer from this issue.

comment:20 Changed 7 years ago by anonymous

I'm having the same problem on WR1043ND r25576. Syslog is the same as the thread starter. I dont think the fact that it's happening every 10 minutes is merely a coincidence. I'm having the exact 10 minutes difference between deauth.

Dmesg says this. Occurred at device startup, and is repeatable. Just restart the router and you'll get it again (provided you have wireless drivers installed)

ath: Could not stop RX, we could be confusing the DMA engine when we start RX up
ath: DMA failed to stop in 10 ms AR_CR=0x00000024 AR_DIAG_SW=0x42000020
ath: DMA failed to stop in 10 ms AR_CR=0x00000024 AR_DIAG_SW=0x42000020
ath: Could not stop RX, we could be confusing the DMA engine when we start RX up
ath: DMA failed to stop in 10 ms AR_CR=0x00000024 AR_DIAG_SW=0x42000020
ath: DMA failed to stop in 10 ms AR_CR=0x00000024 AR_DIAG_SW=0x42000020
ath: Could not stop RX, we could be confusing the DMA engine when we start RX up
ath: DMA failed to stop in 10 ms AR_CR=0x00000024 AR_DIAG_SW=0x42000020

comment:21 Changed 7 years ago by blindbox

That's me. luci-app-statistics nor collectd were installed.

comment:22 Changed 7 years ago by blindbox

On r25596 with no vnstat, everything seems to run fine. I don't see any modification from r25576 to r25596 on ath9k nor ar71xx (which is significant) so I think this issue is vnstat related? A change in ath9k probably makes all statistic apps to hate collecting wireless data.

comment:23 follow-up: Changed 7 years ago by got_milk <ryan.morrison04@…>

I'm intrigued. I'll do a clean build without vnstat/collectd tonight/tomorrow and report back. There was a kernel bump that might have helped things along, but as the modules are built independently I can't say for sure.

I'm on stock firmware now and it's not without its own flaws! DD-WRT is awful on the WNDR3700. If I could get the latency issues to stop on OpenWrt it would be the *perfect* solution.

comment:24 Changed 7 years ago by got_milk <ryan.morrison04@…>

Update: r25596 still exhibits the latency issue, with no statistics at all (both collectd and vnstat have been removed from the build).

However, I have an old WRT310N that uses DD-WRT sitting around doing nothing, so I set it up as a wireless client bridge and connected it to the WNDR3700 and to my Intel client via a wired connection and I cannot reproduce the latency!

comment:25 in reply to: ↑ 23 Changed 7 years ago by anonymous

Yes without the latency issues it would be perfect, but I'm reaching the one year mark with this bug soon, so my hope is leaving :-(.

Replying to got_milk <ryan.morrison04@…>:

I'm intrigued. I'll do a clean build without vnstat/collectd tonight/tomorrow and report back. There was a kernel bump that might have helped things along, but as the modules are built independently I can't say for sure.

I'm on stock firmware now and it's not without its own flaws! DD-WRT is awful on the WNDR3700. If I could get the latency issues to stop on OpenWrt it would be the *perfect* solution.

comment:26 follow-up: Changed 7 years ago by jeyjay

...sad but true. One year of disconnects and lagging.

Still hoping that someday this annoying bug gets solved...

comment:27 in reply to: ↑ 26 Changed 7 years ago by anonymous

I've reproduced it at a dozen times, with several versions.
Always compiled with the ability to debug the ath.

So I often offered to debug it, if I just knew a handy debug level and/or options for that.
But I never got an answer on this, so I don't see what I can do about it anymore :-(.

And after time these tickets just got ignored.

I'm very sad about this, as a commercial vender like Netgear have an OpenWRT variant on which it works flawlessly. And I don't see why we can't get it there in the open source community, even with so many motivated users. (And with nbd as good developer behind. Just not tenacious enough about this particular, in my opinion very, important case.)

Replying to jeyjay:

...sad but true. One year of disconnects and lagging.

Still hoping that someday this annoying bug gets solved...

comment:28 Changed 7 years ago by nbd

Guys, please keep the whining to yourself, it's not helpful in any way for solving this issue. If there was a simple way to get more information to solve this issue, I would have told you already.

The reason why the Netgear firmware works and OpenWrt still has this issue is very simple: Netgear uses the proprietary driver from Atheros. The source code of this driver (which is not publicly available) is awful, but at least a few dozen developers - maybe more - have hacked on it until it reached its level of stability.

ath9k has me working on it on the OpenWrt side, as well as a small number of developers on the linux-wireless side, some from Atheros, some from the community.

Hopefully with this information you'll be able to grasp how there really is no lack of whining users, nor a lack of motivation or attention on the developer side, there simply aren't enough developers to take care of such issues in a timely manner.

The impression that I got from all the feedback I got so far is that the driver stability has been continuously improving over time, with the remaining issues being mostly limited to a few specific client hardware combinations. Be a bit more patient and those issues will go away as well.

comment:29 Changed 7 years ago by got_milk <ryan.morrison04@…>

Playing around a bit I'm noticing that the wireless bitrate seems to be highly inconsistent when I'm associated with the AP - it can vary anywhere from 5.5 Mb/s to 300Mb/s, even when I'm close to the router. Tested with only the Intel/affected client associated to the AP. Not sure if it's relevant but I thought I'd add that.

comment:30 Changed 7 years ago by got_milk <ryan.morrison04@…>

Back to stock firmware again - I need some sense of reliability on wireless and OpenWrt just cannot deliver it for me. If there are ath9k improvements I may consider switching back but for the time being OpenWrt is no longer an option.

comment:31 Changed 7 years ago by got_milk <ryan.morrison04@…>

I see r25779 has made some changes to ath9k, any idea if they'll help out here?

comment:32 Changed 7 years ago by got_milk <ryan.morrison04@…>

Upgraded to r25794, issue still persists but it appears to be less frequent. The "local deauth request" messages are still appearing, exactly every 10 minutes, only with the Intel client, but the connection drops are not matching up and occur more frequently than the "local deauth request"s.

comment:33 Changed 7 years ago by anonymous

Not sure when this appeared in the trunk, but I never saw it on older builds (r25097 as an example)

comment:34 Changed 7 years ago by got_milk <ryan.morrison04@…>

Mar  2 23:06:01 WNDR3700 kern.err kernel: ath: Failed to stop TX DMA in 100 msec after killing last frame

I haven't seen this before, I found this in with the usual "local deauth request" messages, not too long after the router crashed and rebooted for an unknown reason.

comment:35 Changed 7 years ago by malbon

Hi,

I used to have this problem but recently upgraded my kernel on my laptop (with Intel 4695agn) and the problem is now resolved for me. I used to get oops and all sorts of nasty with the old driver. New kernel is Debian Testing 2.6.32-5-amd64. I don't think this is WNDR3700 specific as looking around it seems to be more generic.

Thanks

Mike

comment:36 Changed 7 years ago by anonymous

I am also seeing this issue. My iTouch & Android phone are affected on the 2.4Ghz radio network. WNDR3700, r25799.

Mar  3 09:17:10 OpenWrt daemon.info dnsmasq-dhcp[1948]: DHCPREQUEST(br-lan) 192.168.1.205 00:1d:4f:ad:1b:1b 
Mar  3 09:17:10 OpenWrt daemon.info dnsmasq-dhcp[1948]: DHCPACK(br-lan) 192.168.1.205 00:1d:4f:ad:1b:1b iPod
Mar  3 09:20:44 OpenWrt daemon.info hostapd: wlan0: STA 00:1d:4f:ad:1b:1b IEEE 802.11: deauthenticated due to local deauth request
Mar  3 09:20:47 OpenWrt daemon.info hostapd: wlan0: STA 00:1d:4f:ad:1b:1b IEEE 802.11: authenticated
Mar  3 09:20:47 OpenWrt daemon.info hostapd: wlan0: STA 00:1d:4f:ad:1b:1b IEEE 802.11: associated (aid 1)
Mar  3 09:20:47 OpenWrt daemon.info hostapd: wlan0: STA 00:1d:4f:ad:1b:1b RADIUS: starting accounting session 4D6E56E9-00000015
Mar  3 09:20:47 OpenWrt daemon.info hostapd: wlan0: STA 00:1d:4f:ad:1b:1b WPA: pairwise key handshake completed (RSN)

I believe this problem is not affecting the 5Ghz radio. My son has yet to complain of lag or issues on his XBOX360.

More info:

Compat-wireless backport release: compat-wireless-2011-01-31-19-g74d6d79
Backport based on linux-next.git next-20110225
cfg80211: Calling CRDA to update world regulatory domain
cfg80211: World regulatory domain updated:
cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
cfg80211:     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
cfg80211:     (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
cfg80211:     (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
ar71xx: pll_reg 0xb8050014: 0x11110000
eth1: link up (1000Mbps/Full duplex)
ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
PCI: Enabling device 0000:00:11.0 (0000 -> 0002)
ath: EEPROM regdomain: 0x0
ath: EEPROM indicates default country code should be used
ath: doing EEPROM country->regdmn map search
ath: country maps to regdmn code: 0x3a
ath: Country alpha2 being used: US
ath: Regpair used: 0x3a
ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
Registered led device: ath9k-phy0
ieee80211 phy0: Atheros AR9280 Rev:2 mem=0xb0000000, irq=48
PCI: Enabling device 0000:00:12.0 (0000 -> 0002)
ath: EEPROM regdomain: 0x0
ath: EEPROM indicates default country code should be used
ath: doing EEPROM country->regdmn map search
ath: country maps to regdmn code: 0x3a
ath: Country alpha2 being used: US
ath: Regpair used: 0x3a
ieee80211 phy1: Selected rate control algorithm 'minstrel_ht'
Registered led device: ath9k-phy1
ieee80211 phy1: Atheros AR9280 Rev:2 mem=0xb0010000, irq=49
cfg80211: Calling CRDA for country: US
cfg80211: Regulatory domain changed to country: US
cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
cfg80211:     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
cfg80211:     (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
cfg80211:     (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
cfg80211:     (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
cfg80211:     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
PPP generic driver version 2.4.2
tun: Universal TUN/TAP device driver, 1.6
tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
PPP MPPE Compression module registered
IPv6 over IPv4 tunneling driver
sit0: Disabled Privacy Extensions
Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
ip_tables: (C) 2000-2006 Netfilter Core Team
NET: Registered protocol family 24
nf_conntrack version 0.5.0 (969 buckets, 3876 max)
xt_time: kernel timezone is -0000
nf_conntrack_rtsp v0.6.21 loading
nf_nat_rtsp v0.6.21 loading
eth0: no IPv6 routers present
ip6_tables: (C) 2000-2006 Netfilter Core Team
Registered led device: wndr3700:green:usb
br-lan: no IPv6 routers present
ADDRCONF(NETDEV_UP): wlan0: link is not ready
device wlan0 entered promiscuous mode
br-lan: port 2(wlan0) entering forwarding state
br-lan: port 2(wlan0) entering forwarding state
eth1: no IPv6 routers present
device wlan0 left promiscuous mode
br-lan: port 2(wlan0) entering forwarding state
device wlan0 entered promiscuous mode
br-lan: port 2(wlan0) entering forwarding state
br-lan: port 2(wlan0) entering forwarding state
ADDRCONF(NETDEV_UP): wlan1: link is not ready
device wlan1 entered promiscuous mode
br-lan: port 3(wlan1) entering forwarding state
br-lan: port 3(wlan1) entering forwarding state
device wlan1 left promiscuous mode
br-lan: port 3(wlan1) entering forwarding state
device wlan1 entered promiscuous mode
br-lan: port 3(wlan1) entering forwarding state
br-lan: port 3(wlan1) entering forwarding state
svc: failed to register lockdv1 RPC service (errno 124).
ar71xx-wdt: enabling watchdog timer

comment:37 Changed 7 years ago by got_milk <ryan.morrison04@…>

Upgraded to r25854, no change, still connection drops roughly every 2-5 minutes.

I cannot speak for Android devices - I do have one but haven't used Wi-Fi much on it.

Just double-checked as well and the issue occurs on both 2.4GHz and 5GHz bands, using 20MHz and 40MHz channels.

I also own an Xbox 360 and have no issues on both 2.4GHz and 5GHz. I have a MacBook Pro client I will be testing soon.

comment:38 Changed 7 years ago by jeyjay

Connection drops still persist in r25871 (with 11g and 11g/n) after bugfixing of gcc.

comment:39 Changed 7 years ago by anonymous

I have the same problem with my android phone on 2.4GHz, wasnt there with a 2 month old revision.

comment:40 Changed 7 years ago by nbd

If you see old revisions working better than newer ones, please figure out the exact revision of package/mac80211 where it got worse.

comment:41 Changed 7 years ago by jeyjay

To get things right:

Concerning the following errors

kern.err kernel: ath: DMA failed to stop in 10 ms AR_CR=0x00000024 AR_DIAG_SW=0x42000020
kern.err kernel: ath: Could not stop RX, we could be confusing the DMA engine when we start RX up
...

developers are currently working on it:
http://www.mail-archive.com/ath9k-devel@lists.ath9k.org/msg05051.html

But I do not know if the error as stated in OP

deauthenticated due to local deauth request

is related. Let's hope so.

comment:42 Changed 7 years ago by nbd

please try latest backfire or trunk, stability should be better now.

comment:43 Changed 7 years ago by nbd

In addition to updating to latest, please also copy http://nbd.name/590-ath9k_tid_cleanup_send_bar.patch to package/mac80211/patches and let me know if it affects stability with intel clients.

comment:44 Changed 7 years ago by got_milk <ryan.morrison04@…>

Built and flashed r26018 with nbd's patch above applied. Don't have much time to test tonight but will test first thing tomorrow morning and report back with results.

comment:45 Changed 7 years ago by got_milk <ryan.morrison04@…>

Just to note that on a couple of MacBook Pro clients that routinely were throwing "deauthenticated due to local deauth request" messages in the system log - with the new build, I've only had 3 instances where that appeared (the build has been running for 4 hours now). Far improved over the routine 10-15 minutes of deauthentication and reauthentication!

comment:46 Changed 7 years ago by got_milk <ryan.morrison04@…>

Tested the Intel client this morning, with positive improvements. The "deauthenticated due to local deauth request" messages have stopped occurring, and it appears that the connection drops have stopped. I will do some more extensive testing but so far so good!

comment:47 Changed 7 years ago by got_milk <ryan.morrison04@…>

Did some more extensive testing this morning and afternoon. The issue has not gone away but appears to be occurring less frequently - every 10-15 minutes instead of every 2-5 minutes.

comment:48 Changed 7 years ago by Martynov Nikolay

I have trendnet tew-632 and intel 5300 client.
I did some testing today and can confirm great improvement from a week ago. I had those 'very long pings' before and 'n' mode was almost unusable. Not connection seems to be stable and speed decent with sane pings. Currently I have AP about 5m away now and get speed about 2MB on average, although it seems to depend on other networks around.
I'll do some more testing tomorrow - will report if I have any problems.

As a note. On AP I get a lot of messages like this:
Mar 12 00:01:23 router kern.debug kernel: ieee80211 phy0: release an RX reorder frame due to timeout on earlier frames
Mar 12 00:01:23 router kern.debug kernel: ieee80211 phy0: release an RX reorder frame due to timeout on earlier frames

Not sure whether they are harmless or not.

Anyway, thanks for great improvement!

comment:49 Changed 7 years ago by anonymous

Just got the following problem: at some point connection got kind of 'stuck': pings 1-3sec, download speed 40kb.

Disconnect and reconnect helped.

So I guess original problem still exists, but occurs much less often and is a bit less severe.

comment:50 Changed 7 years ago by jeyjay

System: Asus WL-500gP with ath9k, running r26044 (including latest patches)

My observations:

  1. ping over WIFI (11n mode) is much more stable and constantly low regardless of some other data transfers
  1. DMA errors still occurring:
    device wlan0 entered promiscuous mode
    br-lan: port 2(wlan0) entering forwarding state
    br-lan: port 2(wlan0) entering forwarding state
    device wlan0 left promiscuous mode
    br-lan: port 2(wlan0) entering forwarding state
    device wlan0 entered promiscuous mode
    br-lan: port 2(wlan0) entering forwarding state
    br-lan: port 2(wlan0) entering forwarding state
    ath: Failed to stop TX DMA!
    ath: DMA failed to stop in 10 ms AR_CR=0x00000024 AR_DIAG_SW=0x42000020
    ath: Could not stop RX, we could be confusing the DMA engine when we start RX up
    ath: DMA failed to stop in 10 ms AR_CR=0x00000024 AR_DIAG_SW=0x42000020
    

comment:51 Changed 7 years ago by got_milk <ryan.morrison04@…>

One thing I've noticed in my testing is that before the connection drops out, there are tiny latency spikes occurring in very rapid succession a second or two before the connection finally drops, if that makes sense.

Also, should we possibly consider moving the latency issue into another ticket? The original "deauthenticated due to local deauth request" issue which I started this for has been fixed.

comment:52 Changed 7 years ago by jeyjay

IMHO, if your connection still drops then the problem isn't solved. Only the deauth message disappeared. I need more uptime to tell if things have improved with the latest patches (especially the drop of the connection).

I'm not sure if things (latency, DMA and deauth) are related. Only a developer can tell. For the moment, hastily opening a new ticket would make things more complicated.

comment:53 Changed 7 years ago by nbd

Here's another patch that you can try:
http://nbd.name/540-ath9k_tx_complete_send_bar.patch

comment:54 Changed 7 years ago by jeyjay

Good news: Connection is stable for non-Intel clients in 11n mode. This wasn't the case before the patches. Once in a while I receive DMA errors but they do not affect the stability. Intel clients are not available at the moment.

Now, I compile again with 540-ath9k_tx_complete_send_bar.patch ....

comment:55 Changed 7 years ago by nbd

That patch is only relevant for 11n mode

comment:56 Changed 7 years ago by jeyjay

just after writing the last message I was affected by several short connection drops. But in contrast to former releases I gain a stable connection after several re-connection attempts by the operating system:

Mar 13 13:53:16 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx IEEE 802.11: authenticated
Mar 13 13:53:16 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx IEEE 802.11: associated (aid 1)
Mar 13 13:53:17 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx RADIUS: starting accounting session 4BAD710D-00000065
Mar 13 13:53:17 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Mar 13 13:53:17 hostname daemon.info dnsmasq-dhcp[1770]: DHCPREQUEST(br-lan) 192.168.1.209 00:1a:73:xx:xx:xx 
Mar 13 13:53:17 hostname daemon.info dnsmasq-dhcp[1770]: DHCPACK(br-lan) 192.168.1.209 00:1a:73:xx:xx:xx test-PC
Mar 13 13:53:52 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx IEEE 802.11: authenticated
Mar 13 13:53:52 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx IEEE 802.11: associated (aid 1)
Mar 13 13:53:52 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx RADIUS: starting accounting session 4BAD710D-00000066
Mar 13 13:53:52 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Mar 13 13:53:52 hostname daemon.info dnsmasq-dhcp[1770]: DHCPREQUEST(br-lan) 192.168.1.209 00:1a:73:xx:xx:xx 
Mar 13 13:53:52 hostname daemon.info dnsmasq-dhcp[1770]: DHCPACK(br-lan) 192.168.1.209 00:1a:73:xx:xx:xx test-PC
Mar 13 13:54:22 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx IEEE 802.11: authenticated
Mar 13 13:54:22 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx IEEE 802.11: associated (aid 1)
Mar 13 13:54:22 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx RADIUS: starting accounting session 4BAD710D-00000067
Mar 13 13:54:23 hostname daemon.info hostapd: wlan0: STA 00:1a:73:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Mar 13 13:54:23 hostname daemon.info dnsmasq-dhcp[1770]: DHCPREQUEST(br-lan) 192.168.1.209 00:1a:73:xx:xx:xx 
Mar 13 13:54:23 hostname daemon.info dnsmasq-dhcp[1770]: DHCPACK(br-lan) 192.168.1.209 00:1a:73:xx:xx:xx test-PC

comment:57 Changed 7 years ago by got_milk <ryan.morrison04@…>

Issue still occurring on r26109 with 540-ath9k_tx_complete_send_bar.patch applied. Doesn't seem any better or worse.


comment:58 Changed 7 years ago by jeyjay

Using r26044 with 540-ath9k_tx_complete_send_bar.patch applied. My observation: Ping OK, speed OK and DMA messages disappeared. Still some re-authentication troubles as described in previous post.

comment:59 Changed 7 years ago by jeyjay

I have to correct myself... the DMA errors are still there.

comment:60 Changed 7 years ago by jeyjay

now, after one and a half day of uptime it is not possible to connect anymore:

did not acknowledge authentication response
disassociated due to inactivity
deauthenticated due to inactivity

comment:61 Changed 7 years ago by got_milk <ryan.morrison04@…>

Update:

Now running r26185 with patches from this ticket applied. I have performed some extensive testing and here are my results:

This issue persists across all Intel driver versions I can find. Namely the 13.3.x, 13.4.x and brand new 13.5.x series of drivers all reproduce this issue.

The latency drops are prefaced by higher than normal latency over wireless. For example, ping times which are normally 3ms will jump to 30-50ms, then 200-300ms immediately before connection drop. The drop lasts on average 2-3 seconds and when connection is established ping times are well over 1000ms for one iteration or two. I cannot find a pattern to match when the connection drops occur.

Higher loads on wireless seem to make the issue easier to reproduce. While performing simple web browsing or e-mails, this issue occurred far less frequently (I could only reproduce once or twice in my testing). However, while playing an online game or engaging in a VoIP call, the connection drops occurred far more frequently.

No messages are appearing in the system or kernel logs during these connection drops. Namely, the "deauthenticated due to local deauth request" messages have disappeared for all clients. Wired and other wireless connections appear to not be affected during these connection drops as well.

comment:62 Changed 7 years ago by nbd

  • Resolution set to fixed
  • Status changed from new to closed

the inactivity timeout on assoc issue should finally be gone completely with r26251

comment:63 Changed 7 years ago by jeyjay

follow-up tickets:

for unstable intel clients and latency spikes with ath9k 11n is #9099.

I reopened #8446 for dying (not unstable) wireless with at9k 11n.

comment:64 Changed 7 years ago by igor

  • Resolution fixed deleted
  • Status changed from closed to reopened

"deauthenticated due to local deauth request" isn't fixed with intel clients. Tested mac80211 from backfire r26317 and from trunk r26316. Devices - WNDR3700 and WRT160NL.

root@OpenWrt:~# logread | grep deauth   
Mar 28 12:09:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 12:19:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 12:29:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 12:39:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 12:49:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 12:59:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 13:09:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 13:19:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 13:29:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 13:39:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 13:49:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 13:59:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 14:09:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 14:19:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request

comment:65 follow-up: Changed 7 years ago by nbd

Interesting - disconnect every 10 minutes. Please show a log that is not filtered by grep, that one does not contain any useful information.

comment:66 Changed 7 years ago by Dmitry Tunin <hanipouspilot@…>

I do not get 'death request', but with Intel client router authentificates many times.
Build r26255

Mar 28 15:48:12 OpenWrt daemon.info dnsmasq-dhcp[1382]: DHCPACK(br-lan) 192.168.1.131 00:23:76:4e:18:23 
Mar 28 16:04:24 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:04:24 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:04:24 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:04:27 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:04:27 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:04:27 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:04:30 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:04:30 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:04:30 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:04:33 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:04:33 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:04:33 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:04:38 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:04:38 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:04:38 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:04:41 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:04:41 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:04:41 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:04:45 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:04:45 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:04:45 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:04:48 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:04:48 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:04:48 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:04:51 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:04:51 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:04:51 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:04:54 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:04:54 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:04:54 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:07:20 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:07:20 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:07:20 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:07:20 OpenWrt daemon.info dnsmasq-dhcp[1382]: DHCPREQUEST(br-lan) 192.168.1.173 00:13:e8:78:33:8b 
Mar 28 16:07:20 OpenWrt daemon.info dnsmasq-dhcp[1382]: DHCPACK(br-lan) 192.168.1.173 00:13:e8:78:33:8b Natasha
Mar 28 16:07:23 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:07:23 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:07:23 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:07:34 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:07:34 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:07:34 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:07:37 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:07:37 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:07:37 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:07:40 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:07:40 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:07:40 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:07:43 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:07:43 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:07:43 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:07:50 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:07:50 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:07:50 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:07:53 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:07:53 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:07:53 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:07:56 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:07:56 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:07:56 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:07:59 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:07:59 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:07:59 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:08:03 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:08:03 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:08:03 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:08:06 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:08:06 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:08:06 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:08:09 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:08:09 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:08:09 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:08:12 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:08:12 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:08:12 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:08:15 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:08:15 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:08:15 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:20:31 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:20:31 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:20:31 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:20:35 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:20:35 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:20:35 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:20:51 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:20:51 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:20:51 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:20:56 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:20:56 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:20:56 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:20:59 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:20:59 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:20:59 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:21:15 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:21:15 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:21:15 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:21:52 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:21:52 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:21:52 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:22:10 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:22:10 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:22:10 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:22:29 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: authenticated
Mar 28 16:22:29 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b IEEE 802.11: associated (aid 1)
Mar 28 16:22:29 OpenWrt daemon.info hostapd: wlan0: STA 00:13:e8:78:33:8b WPA: pairwise key handshake completed (RSN)
Mar 28 16:25:04 OpenWrt daemon.info hostapd: wlan0: STA 00:23:76:4e:18:23 IEEE 802.11: authenticated
Mar 28 16:25:04 OpenWrt daemon.info hostapd: wlan0: STA 00:23:76:4e:18:23 IEEE 802.11: associated (aid 2)
Mar 28 16:25:04 OpenWrt daemon.info hostapd: wlan0: STA 00:23:76:4e:18:23 WPA: pairwise key handshake completed (RSN)
Mar 28 16:25:04 OpenWrt daemon.info dnsmasq-dhcp[1382]: DHCPDISCOVER(br-lan) 00:23:76:4e:18:23 
Mar 28 16:25:04 OpenWrt daemon.info dnsmasq-dhcp[1382]: DHCPOFFER(br-lan) 192.168.1.131 00:23:76:4e:18:23 
Mar 28 16:25:04 OpenWrt daemon.info dnsmasq-dhcp[1382]: DHCPREQUEST(br-lan) 192.168.1.131 00:23:76:4e:18:23 
Mar 28 16:25:04 OpenWrt daemon.info dnsmasq-dhcp[1382]: DHCPACK(br-lan) 192.168.1.131 00:23:76:4e:18:23 

It did not happen in earlier builds.

comment:67 Changed 7 years ago by dirtyfreebooter <openwrt-devel@…>

With my D-LINK DIR-825, basically same hardware as the 3700, in the last week or two of trunk builds, I starting seeing multiple authentication requests in one shot, as described above, associating with a Linksys 610Nv2 in client bridge mode. Since I started using OpenWrt and the DIR-825, I never saw that behavior with the two routers, now its repeatable on every boot when they first associate with each other.

comment:68 in reply to: ↑ 65 Changed 7 years ago by igor

Replying to nbd:

Interesting - disconnect every 10 minutes. Please show a log that is not filtered by grep, that one does not contain any useful information.

WRT160NL, backfire base with mac80211 from trunk r26316:

Mar 28 12:03:11 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: authenticated
Mar 28 12:03:11 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: associated (aid 1)
Mar 28 12:03:11 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 WPA: pairwise key handshake completed (RSN)
Mar 28 12:03:11 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPREQUEST(br-lan) 172.31.254.3 00:21:6a:13:79:a8 
Mar 28 12:03:11 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPACK(br-lan) 172.31.254.3 00:21:6a:13:79:a8 T500
Mar 28 12:03:14 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPINFORM(br-lan) 172.31.254.3 00:21:6a:13:79:a8 
Mar 28 12:03:14 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPACK(br-lan) 172.31.254.3 00:21:6a:13:79:a8 T500
Mar 28 12:05:50 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPINFORM(br-lan) 172.31.254.3 00:21:6a:13:79:a8 
Mar 28 12:05:50 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPACK(br-lan) 172.31.254.3 00:21:6a:13:79:a8 T500
Mar 28 12:09:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 12:09:56 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: authenticated
Mar 28 12:09:56 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: associated (aid 1)
Mar 28 12:09:56 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 WPA: pairwise key handshake completed (RSN)
Mar 28 12:09:56 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPREQUEST(br-lan) 172.31.254.3 00:21:6a:13:79:a8 
Mar 28 12:09:56 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPACK(br-lan) 172.31.254.3 00:21:6a:13:79:a8 T500
Mar 28 12:19:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 12:19:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: authenticated
Mar 28 12:19:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: associated (aid 1)
Mar 28 12:19:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 WPA: pairwise key handshake completed (RSN)
Mar 28 12:19:53 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPREQUEST(br-lan) 172.31.254.3 00:21:6a:13:79:a8 
Mar 28 12:19:53 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPACK(br-lan) 172.31.254.3 00:21:6a:13:79:a8 T500
Mar 28 12:29:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 12:29:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: authenticated
Mar 28 12:29:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: associated (aid 1)
Mar 28 12:29:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 WPA: pairwise key handshake completed (RSN)
Mar 28 12:29:53 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPREQUEST(br-lan) 172.31.254.3 00:21:6a:13:79:a8 
Mar 28 12:29:53 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPACK(br-lan) 172.31.254.3 00:21:6a:13:79:a8 T500
Mar 28 12:39:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 12:39:54 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: authenticated
Mar 28 12:39:54 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: associated (aid 1)
Mar 28 12:39:54 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 WPA: pairwise key handshake completed (RSN)
Mar 28 12:39:54 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPREQUEST(br-lan) 172.31.254.3 00:21:6a:13:79:a8 
Mar 28 12:39:54 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPACK(br-lan) 172.31.254.3 00:21:6a:13:79:a8 T500
Mar 28 12:49:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 12:49:56 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: authenticated
Mar 28 12:49:56 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: associated (aid 1)
Mar 28 12:49:56 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 WPA: pairwise key handshake completed (RSN)
Mar 28 12:49:56 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPREQUEST(br-lan) 172.31.254.3 00:21:6a:13:79:a8 
Mar 28 12:49:56 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPACK(br-lan) 172.31.254.3 00:21:6a:13:79:a8 T500
Mar 28 12:59:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 12:59:56 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: authenticated
Mar 28 12:59:56 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: associated (aid 1)
Mar 28 12:59:56 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 WPA: pairwise key handshake completed (RSN)
Mar 28 12:59:56 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPREQUEST(br-lan) 172.31.254.3 00:21:6a:13:79:a8 
Mar 28 12:59:56 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPACK(br-lan) 172.31.254.3 00:21:6a:13:79:a8 T500
Mar 28 13:09:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 13:09:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: authenticated
Mar 28 13:09:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: associated (aid 1)
Mar 28 13:09:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 WPA: pairwise key handshake completed (RSN)
Mar 28 13:09:53 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPREQUEST(br-lan) 172.31.254.3 00:21:6a:13:79:a8 
Mar 28 13:09:53 OpenWrt daemon.info dnsmasq-dhcp[1121]: DHCPACK(br-lan) 172.31.254.3 00:21:6a:13:79:a8 T500
Mar 28 13:19:53 OpenWrt daemon.info hostapd: wlan0: STA 00:21:6a:13:79:a8 IEEE 802.11: deauthenticated due to local deauth request

WNDR3700, backfire base with mac80211 r26317:

Mar 28 18:44:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 18:44:09 OpenWrt daemon.info hostapd: wlan0: STA 00:18:de:b8:be:7b WPA: group key handshake completed (RSN)
Mar 28 18:44:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: authenticated
Mar 28 18:44:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: associated (aid 1)
Mar 28 18:44:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 WPA: pairwise key handshake completed (RSN)
Mar 28 18:54:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 18:54:09 OpenWrt daemon.info hostapd: wlan0: STA 00:18:de:b8:be:7b WPA: group key handshake completed (RSN)
Mar 28 18:54:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: authenticated
Mar 28 18:54:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: associated (aid 1)
Mar 28 18:54:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 WPA: pairwise key handshake completed (RSN)
Mar 28 19:04:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 19:04:09 OpenWrt daemon.info hostapd: wlan0: STA 00:18:de:b8:be:7b WPA: group key handshake completed (RSN)
Mar 28 19:04:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: authenticated
Mar 28 19:04:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: associated (aid 1)
Mar 28 19:04:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 WPA: pairwise key handshake completed (RSN)
Mar 28 19:14:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: deauthenticated due to local deauth request
Mar 28 19:14:09 OpenWrt daemon.info hostapd: wlan0: STA 00:18:de:b8:be:7b WPA: group key handshake completed (RSN)
Mar 28 19:14:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: authenticated
Mar 28 19:14:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 IEEE 802.11: associated (aid 1)
Mar 28 19:14:09 OpenWrt daemon.info hostapd: wlan1: STA 00:21:5d:97:e9:a4 WPA: pairwise key handshake completed (RSN)

comment:69 Changed 7 years ago by nbd

Please run this:

killall hostapd
hostapd -dd /var/run/hostapd-phy0.conf 2>&1 | tee /tmp/log.txt

Wait until a few disconnects/reconnects had happened, then abort and upload /tmp/log.txt here.

comment:70 Changed 7 years ago by igor

WNDR3700, wlan1 with only one intel's sta:

http://goo.gl/I3hJx

comment:71 Changed 7 years ago by nbd

Looks like the Intel STA is either not waking up from powersave at rekey time, or it's discarding the incoming packets. Do you have a third device that you could use to capture the traffic between the AP and the Station while this happens? (It might help to disable 802.11n on the AP to increase the reliability of the traffic capture).

comment:72 Changed 7 years ago by igor

"deauthenticated due to local deauth request" doesn't take place with 11g for me. Only 11n is affected (with windows drivers for Intel cards). But it happend earlier and, IIRC, last time was around September 2010 or somewhere so.

I have only one 11n laptop for testing this problem at home. Maybe I'll find another in near future, so you can describe in detail what did you want to see.

comment:73 Changed 7 years ago by nbd

OK, if you can't make an external capture at this point, then please make one from the AP itself.

iw wlan1 interface add mon0 type monitor
ifconfig mon0 up
tcpdump -ni mon0 -w /tmp/file.pcap -s 3000

then reproduce the issue a few times, stop tcpdump and send me /tmp/file.pcap

I don't know if this will be enough to figure out the cause of this issue, but we'll see...

comment:74 Changed 7 years ago by nbd

Thanks for the dump. I took a look on it and it seems that we can rule out powersave or frame reception issues. At rekey time the AP sends its EAP requests and the Intel client ACKs every single one of them.
Please give me some details on the Intel client, e.g. what card is it, what operating system, what driver version, etc.

comment:75 Changed 7 years ago by Dmitry Tunin <hanipouspilot@…>

At rekey time the AP sends its EAP requests and the Intel client ACKs every single one of them.

That is excatly what happens. I hve same problem.
Intel 4965AGN, Windows Vista, driver 13.4.0.139 date 07.10.2010

comment:76 Changed 7 years ago by Dmitry Tunin <hanipouspilot@…>

I upgraded Intel driver to 13.5 (last).
It seems that it ACKs only twice according to log. Not many times.
I will test more.

comment:77 Changed 7 years ago by igor

Dump was taken with Intel 5100 card working under Windows XP Professional SP3 x32 with driver 13.4.0.9. Driver's power management was set to default value and laptop was working from AC (i.e. minimum power saving).
With two another laptops I see exactly the same issue. They have 5100 and 5300 cards, working under Windows 7 Professional x32 and x64, driver version should be the same (from 13.4.0.0 Intel's package) or older.

Some time ago I tested different older driver versions for WinXP and I got this problem with all of them. I'll test new Intel's 13.5 package soon.

comment:78 Changed 7 years ago by nbd

Please copy http://nbd.name/900-nl80211_enable_qosdata.patch to package/hostapd/patches, rebuild hostapd, reinstall wpad-mini on your device and see if you can still reproduce the issue.

comment:79 Changed 7 years ago by igor

Build hostapd from trunk with this patch - no more "deauthenticated due to local deauth request". Thanks!

Can you backport this patch to backfire?

comment:80 Changed 7 years ago by nbd

Nice! I'm happy to finally get rid of this bug. Sure, I will backport the patch to backfire.

comment:81 Changed 7 years ago by Dmitry Tunin <hanipouspilot@…>

And what about multiple ACKs? I did not test this patch yet.

comment:82 Changed 7 years ago by nbd

Then go for it! :)

comment:83 Changed 7 years ago by Dmitry Tunin <hanipouspilot@…>

Shall I reinstall hostapd or just wpad-mini?

comment:84 Changed 7 years ago by nbd

wpad-mini contains hostapd (+wpa_supplicant), so reinstall whatever you have on the device already.

comment:85 Changed 7 years ago by Dmitry Tunin <hanipouspilot@…>

It works! No multiple ACKs anymore. Big thks.

comment:86 Changed 7 years ago by nbd

  • Resolution set to fixed
  • Status changed from reopened to closed

Thanks for testing. Fix committed in r26367, backported in r26370

comment:87 Changed 4 years ago by jow

  • Milestone changed from Attitude Adjustment 12.09 to Barrier Breaker 14.07

Milestone Attitude Adjustment 12.09 deleted

Add Comment

Modify Ticket

Action
as closed .
The resolution will be deleted. Next status will be 'reopened'.
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.