All of lore.kernel.org
 help / color / mirror / Atom feed
* [ath9k-devel] Auth Packet TX Delay
@ 2012-11-20 18:45 Robert Shade
  2013-01-15 22:06   ` [ath9k-devel] " Robert Shade
  0 siblings, 1 reply; 73+ messages in thread
From: Robert Shade @ 2012-11-20 18:45 UTC (permalink / raw)
  To: ath9k-devel

I'm seeing a periodic issue where the device seems to get stuck in a
state where the TX of authentication packets is delayed so that
authentication fails.  The log snippet below shows the auth packets
getting queued after each "wlan0: send auth to XX", but they're not
actually sent until after it gives up and restarts scanning.  Once the
device gets into this state, it stays in a SCAN->AUTH->AUTH
FAILED->SCAN cycle indefinitely.  However, if I do a ifconfig wlan0
down, the device recovers and works correctly for a few minutes to
hours.

This is with the latest compat-drivers.  The authentication is EAP-TLS
and it's in an environment where it periodically roams using
wpa_supplicant's bgscan.

Nov 20 11:24:33 MR89253 kernel: ath: phy0: Reset TX queue: 0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: tx ok 0x0 err 0x0 desc
0x10f eol 0x10f urn 0x0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Reset TX queue: 1
Nov 20 11:24:33 MR89253 kernel: ath: phy0: tx ok 0x0 err 0x0 desc
0x10f eol 0x10f urn 0x0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Reset TX queue: 2
Nov 20 11:24:33 MR89253 kernel: ath: phy0: tx ok 0x0 err 0x0 desc
0x10f eol 0x10f urn 0x0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Reset TX queue: 3
Nov 20 11:24:33 MR89253 kernel: ath: phy0: tx ok 0x0 err 0x0 desc
0x10f eol 0x10f urn 0x0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Reset TXQ, inactive queue: 4
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Reset TXQ, inactive queue: 5
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Reset TXQ, inactive queue: 6
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Reset TXQ, inactive queue: 7
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Reset TX queue: 8
Nov 20 11:24:33 MR89253 kernel: ath: phy0: tx ok 0x0 err 0x0 desc
0x10f eol 0x10f urn 0x0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Reset TX queue: 9
Nov 20 11:24:33 MR89253 kernel: ath: phy0: tx ok 0x0 err 0x0 desc
0x10f eol 0x10f urn 0x0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: ver 64.1 opmode 2 chan 2437 Mhz/0xc0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: ah->misc_mode 0x4
Nov 20 11:24:33 MR89253 kernel: ath: phy0: enabling ADC Gain Calibration
Nov 20 11:24:33 MR89253 kernel: ath: phy0: enabling ADC DC Calibration
Nov 20 11:24:33 MR89253 kernel: ath: phy0: enabling IQ Calibration
Nov 20 11:24:33 MR89253 kernel: ath: phy0: starting ADC Gain Calibration
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Enable MIB counters
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Restore history: opmode 2
chan 2437 Mhz/0xc0 is_scanning=0 ofdm:8 cck:6
Nov 20 11:24:33 MR89253 kernel: ath: phy0: **** ofdmlevel 8=>8,
rssi=67[lo=7 hi=40]
Nov 20 11:24:33 MR89253 kernel: ath: phy0: ** ch 2437: level
3=>7[def:3] cycpwrThr1[level]=14 ini=6
Nov 20 11:24:33 MR89253 kernel: ath: phy0: ** ch 2437: level
3=>7[def:3] cycpwrThr1Ext[level]=14 ini=6
Nov 20 11:24:33 MR89253 kernel: ath: phy0: ANI parameters: SI=7,
ofdmWS=on FS=2 MRCcck=off listenTime=0 ofdmErrs=0 cckErrs=0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: ** ch 2437: level
2=>6[def:2] firstep[level]=10 ini=2
Nov 20 11:24:33 MR89253 kernel: ath: phy0: ** ch 2437: level
2=>6[def:2] firstep_low[level]=14 ini=6
Nov 20 11:24:33 MR89253 kernel: ath: phy0: ANI parameters: SI=7,
ofdmWS=on FS=6 MRCcck=off listenTime=0 ofdmErrs=0 cckErrs=0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: ** ch 2437: ofdm weak signal: on=>off
Nov 20 11:24:33 MR89253 kernel: ath: phy0: ANI parameters: SI=7,
ofdmWS=off FS=6 MRCcck=off listenTime=0 ofdmErrs=0 cckErrs=0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: **** ccklevel 6=>6,
rssi=67[lo=7 hi=40]
Nov 20 11:24:33 MR89253 kernel: ath: phy0: New interrupt mask 0xf4040071
Nov 20 11:24:33 MR89253 kernel: ath: phy0: new IMR 0x918404b0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Do not enable IER ref count -1
Nov 20 11:24:33 MR89253 kernel: ath: phy0: STA is not yet
associated..skipping beacon config
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Beacon already configured
for a station interface
Nov 20 11:24:33 MR89253 kernel: wlan0: Inserted STA 00:24:6c:74:0a:40
Nov 20 11:24:33 MR89253 kernel: wlan0: send auth to 00:24:6c:74:0a:40 (try 1/3)
Nov 20 11:24:33 MR89253 kernel: ath: phy0: transmitting packet, skb:
ffff880137846a80
Nov 20 11:24:33 MR89253 kernel: ath: phy0: qnum: 0, txq depth: 0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: TXDP[0] = 378480c8 (ffff8800378480c8)
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Enable TXE on queue: 0
Nov 20 11:24:33 MR89253 NetworkManager[1821]: <info> (wlan0):
supplicant interface state: scanning -> authenticating
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: RTM_NEWLINK: operstate=0
ifi_flags=0x1003 ([UP])
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: RTM_NEWLINK,
IFLA_IFNAME: Interface 'wlan0' added
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: if_removed
already cleared - ignore event
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Event message available
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: New station
00:24:6c:74:0a:40
Nov 20 11:24:33 MR89253 kernel: wlan0: send auth to 00:24:6c:74:0a:40 (try 2/3)
Nov 20 11:24:33 MR89253 kernel: ath: phy0: transmitting packet, skb:
ffff8801265cc2c0
Nov 20 11:24:33 MR89253 kernel: ath: phy0: qnum: 0, txq depth: 1
Nov 20 11:24:33 MR89253 kernel: ath: phy0: link[0]
(ffff8800378480c8)=37847568 (ffff880037847568)
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Enable TXE on queue: 0
Nov 20 11:24:33 MR89253 kernel: wlan0: send auth to 00:24:6c:74:0a:40 (try 3/3)
Nov 20 11:24:33 MR89253 kernel: ath: phy0: transmitting packet, skb:
ffff8801261aac80
Nov 20 11:24:33 MR89253 kernel: ath: phy0: qnum: 0, txq depth: 2
Nov 20 11:24:33 MR89253 kernel: ath: phy0: link[0]
(ffff880037847568)=378465f8 (ffff8800378465f8)
Nov 20 11:24:33 MR89253 kernel: ath: phy0: Enable TXE on queue: 0
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Event message available
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Delete station
00:24:6c:74:0a:40
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Event message available
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: MLME event 37;
timeout with 00:24:6c:74:0a:40
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: wlan0: Event
AUTH_TIMED_OUT (14) received
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: wlan0: SME:
Authentication timed out
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: Added BSSID
00:24:6c:74:0a:40 into blacklist
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: wlan0: Another BSS in
this ESS has been seen; try it next
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: BSSID 00:24:6c:74:0a:40
blacklist count incremented to 2
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: wlan0: Setting scan
request: 0 sec 100000 usec
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: wlan0: State:
AUTHENTICATING -> DISCONNECTED
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]:
wpa_driver_nl80211_set_operstate: operstate 0->0 (DORMANT)
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: netlink: Operstate:
linkmode=-1, operstate=5
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: EAPOL: External
notification - portEnabled=0
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: EAPOL: Supplicant port
status: Unauthorized
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: EAPOL: External
notification - portValid=0
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: EAPOL: Supplicant port
status: Unauthorized
Nov 20 11:24:33 MR89253 kernel: wlan0: authentication with
00:24:6c:74:0a:40 timed out
Nov 20 11:24:33 MR89253 kernel: wlan0: Removed STA 00:24:6c:74:0a:40
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1
Nov 20 11:24:33 MR89253 NetworkManager[1821]: <info> (wlan0):
supplicant interface state: authenticating -> disconnected
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: wlan0: State:
DISCONNECTED -> SCANNING
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: wlan0: Starting AP scan
for wildcard SSID
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2412 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2417 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2422 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2427 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2432 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2437 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2442 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2447 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2452 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2457 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2462 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2467 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2472 MHz
Nov 20 11:24:33 MR89253 wpa_supplicant[1841]: nl80211: Scan frequency 2484 MHz
Nov 20 11:24:34 MR89253 kernel: ath: phy0: AWAKE -> FULL-SLEEP
Nov 20 11:24:34 MR89253 kernel: wlan0: Destroyed STA 00:24:6c:74:0a:40
Nov 20 11:24:34 MR89253 kernel: ath: phy0: FULL-SLEEP -> AWAKE
Nov 20 11:24:34 MR89253 kernel: ath: phy0: AWAKE -> FULL-SLEEP
Nov 20 11:24:34 MR89253 kernel: ath: phy0: FULL-SLEEP -> AWAKE
Nov 20 11:24:34 MR89253 kernel: ath: phy0: Set channel: 2437 MHz type: 0
Nov 20 11:24:34 MR89253 kernel: ath: phy0: NF calibrated [ctl] [chain 0] is -50
Nov 20 11:24:34 MR89253 kernel: ath: phy0: NF[0] (-50) > MAX (-80),
correcting to MAX
Nov 20 11:24:34 MR89253 kernel: ath: phy0: NF calibrated [ctl] [chain 1] is -50
Nov 20 11:24:34 MR89253 kernel: ath: phy0: NF[1] (-50) > MAX (-80),
correcting to MAX
Nov 20 11:24:34 MR89253 kernel: ath: phy0: NF calibrated [ctl] [chain 2] is -50
Nov 20 11:24:34 MR89253 kernel: ath: phy0: NF[2] (-50) > MAX (-80),
correcting to MAX
Nov 20 11:24:34 MR89253 kernel: ath: phy0: Stopping ANI
Nov 20 11:24:34 MR89253 kernel: ath: phy0: disable IER
Nov 20 11:24:34 MR89253 kernel: ath: phy0: Disable MIB counters
Nov 20 11:24:34 MR89253 kernel: ath: phy0: TX complete: skb: ffff880137846a80
Nov 20 11:24:34 MR89253 kernel: ath: phy0: TX complete: skb: ffff8801265cc2c0
Nov 20 11:24:34 MR89253 kernel: ath: phy0: TX complete: skb: ffff8801261aac80

17:00.0 Network controller: Atheros Communications Inc. AR9160
Wireless Network Adapter [AR9001 802.11(a)bgn] (rev 01)
	Subsystem: Ubiquiti Networks, Inc. SR71-A 802.11abgn Wireless Mini PCI Adapter
	Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr-
Stepping- SERR- FastB2B- DisINTx-
	Status: Cap+ 66MHz+ UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort-
<TAbort- <MAbort- >SERR- <PERR- INTx-
	Latency: 168, Cache Line Size: 32 bytes
	Interrupt: pin A routed to IRQ 18
	Region 0: Memory@fd5f0000 (32-bit, non-prefetchable) [size=64K]
	Capabilities: [44] Power Management version 2
		Flags: PMEClk- DSI- D1- D2- AuxCurrent=100mA PME(D0+,D1-,D2-,D3hot+,D3cold-)
		Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
	Kernel driver in use: ath9k
	Kernel modules: ath9k

I should also mention that this device periodically suffers from the
DMA issues like the following:

Nov 20 13:17:57 MR89253 kernel: ath: phy0: Failed to stop TX DMA, queues=0x005!
Nov 20 13:36:49 MR89253 kernel: ath: phy0: Failed to stop TX DMA, queues=0x001!
Nov 20 13:40:14 MR89253 kernel: ath: phy0: Failed to stop TX DMA, queues=0x005!

These do not seem to coincide with the issue above.

Please let me know if you need any additional information or testing
done.  Thanks.

^ permalink raw reply	[flat|nested] 73+ messages in thread

end of thread, other threads:[~2013-03-27 16:33 UTC | newest]

Thread overview: 73+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2012-11-20 18:45 [ath9k-devel] Auth Packet TX Delay Robert Shade
2013-01-15 22:06 ` Robert Shade
2013-01-15 22:06   ` [ath9k-devel] " Robert Shade
2013-01-16 23:09   ` Adrian Chadd
2013-01-16 23:09     ` [ath9k-devel] " Adrian Chadd
2013-01-17  1:00     ` Robert Shade
2013-01-17  1:00       ` [ath9k-devel] " Robert Shade
2013-01-17  3:12       ` Adrian Chadd
2013-01-17  3:12         ` [ath9k-devel] " Adrian Chadd
2013-02-06  2:51         ` Robert Shade
2013-02-06  2:51           ` [ath9k-devel] " Robert Shade
2013-02-06  3:08           ` Adrian Chadd
2013-02-06  3:08             ` [ath9k-devel] " Adrian Chadd
2013-02-06 12:53             ` Robert Shade
2013-02-06 12:53               ` [ath9k-devel] " Robert Shade
2013-02-06 22:58               ` Robert Shade
2013-02-06 22:58                 ` [ath9k-devel] " Robert Shade
2013-02-07  5:06                 ` Adrian Chadd
2013-02-07  5:06                   ` [ath9k-devel] " Adrian Chadd
2013-02-07 16:25                   ` David Littell
2013-02-07 16:25                     ` David Littell
2013-02-07 19:43                   ` Robert Shade
2013-02-07 19:43                     ` [ath9k-devel] " Robert Shade
2013-02-07 21:40                     ` Adrian Chadd
2013-02-07 21:40                       ` [ath9k-devel] " Adrian Chadd
2013-02-08 18:48                       ` Robert Shade
2013-02-08 18:48                         ` [ath9k-devel] " Robert Shade
2013-02-09  7:39                         ` Adrian Chadd
2013-02-09  7:39                           ` [ath9k-devel] " Adrian Chadd
2013-03-24 18:55                           ` Robert Shade
2013-03-24 18:55                             ` [ath9k-devel] " Robert Shade
2013-03-24 21:52                             ` Adrian Chadd
2013-03-24 21:52                               ` [ath9k-devel] " Adrian Chadd
2013-03-24 22:40                               ` Robert Shade
2013-03-24 22:40                                 ` [ath9k-devel] " Robert Shade
2013-03-24 22:58                                 ` Christian Lamparter
2013-03-24 22:58                                   ` [ath9k-devel] " Christian Lamparter
2013-03-25  0:03                                   ` Adrian Chadd
2013-03-25  0:03                                     ` [ath9k-devel] " Adrian Chadd
2013-03-25  2:23                                     ` Adrian Chadd
2013-03-25  2:23                                       ` [ath9k-devel] " Adrian Chadd
2013-03-25 16:12                                       ` Christian Lamparter
2013-03-25 16:12                                         ` [ath9k-devel] " Christian Lamparter
2013-03-25 16:45                                         ` Adrian Chadd
2013-03-25 16:45                                           ` [ath9k-devel] " Adrian Chadd
2013-03-26 12:21                                           ` Robert Shade
2013-03-26 12:21                                             ` [ath9k-devel] " Robert Shade
2013-03-26 13:23                                             ` Robert Shade
2013-03-26 13:23                                               ` [ath9k-devel] " Robert Shade
2013-03-26 16:28                                             ` Adrian Chadd
2013-03-26 16:28                                               ` [ath9k-devel] " Adrian Chadd
2013-03-26 16:29                                               ` Robert Shade
2013-03-26 16:29                                                 ` [ath9k-devel] " Robert Shade
2013-03-26 17:13                                                 ` Ben Greear
2013-03-26 17:13                                                   ` Ben Greear
2013-03-26 17:16                                                   ` Adrian Chadd
2013-03-26 17:16                                                     ` Adrian Chadd
2013-03-26 17:27                                                     ` Ben Greear
2013-03-26 17:27                                                       ` Ben Greear
2013-03-26 17:33                                                       ` Adrian Chadd
2013-03-26 17:33                                                         ` Adrian Chadd
2013-03-26 17:45                                                         ` Ben Greear
2013-03-26 17:45                                                           ` Ben Greear
2013-03-27  0:55                                                   ` Robert Shade
2013-03-27  0:55                                                     ` Robert Shade
2013-03-27  3:11                                                     ` Robert Shade
2013-03-27  3:11                                                       ` Robert Shade
2013-03-27 16:33                                                       ` Adrian Chadd
2013-03-27 16:33                                                         ` Adrian Chadd
2013-03-26 17:14                                                 ` Adrian Chadd
2013-03-26 17:14                                                   ` [ath9k-devel] " Adrian Chadd
2013-03-26 14:13                                           ` Marco Fonseca
2013-03-26 14:13                                             ` [ath9k-devel] " Marco Fonseca

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.