On Tue, 2012-01-10 at 13:49 -0500, Dave Jones wrote:
> For the last few releases, iwlwifi has been getting consistently worse
> wrt reliability for me. The failure mode has varied, from the chip just
> locking up with no tx/rx of packets with nothing being logged, to
> microcode warnings, and spewing 'Tx aggregation enabled' messages over and over.
You might want to CC linux-wireless@vger too...
> The merge post 3.2 has made these problems a lot worse. Before, these
> lock-ups were happening once or twice a day. Now they happen several times an hour
> (and after the first one, they seem more frequent). When they happen,
> unloading and reloading the module is the only way for me to get working wireless again.
> They may happen more frequently when the laptop is not idle.
>
> I did a bisect of the changes since 3.2, which pointed at 76bc10fcd128ad028cf77c62e179cd20dc2ffecf
> as being the culprit, but to be honest I'm not 100% convinced.
>
> Because every step of the way during the bisect, I saw different failure modes,
> so when I marked something as 'good', it meant "doesn't lock up in the same way",
> even though it may be symptomatic of the same problem.
>
> The specific chip I'm using is a 5300 in a Dell Adamo, connecting to
> an Apple airport extreme (current model) in N mode.
>
> Dave
>
> --
> To unsubscribe from this list: send the line "unsubscribe netdev" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> [ 173.145695] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 869
> [ 173.147133] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 101
> [ 173.147545] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [ 173.148050] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:88 tid = 0
I am missing logs here... You seem to reauthenticate but I can't see disconnection... weird
> [ 192.805102] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [ 192.807392] wlan0: authenticated
> [ 192.814840] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> 1633, next_recl = 139
Stop AGG before we are associated ?!
Is that leftovers from the previous association that was torn down ?
> [ 192.818669] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
> [ 192.818939] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
> [ 192.819206] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
> [ 192.824157] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
Associating to another AP ? A band maybe ?
> [ 192.828014] wlan0: RX ReassocResp from b8:c7:5d:0c:39:87 (capab=0x431
> status=0 aid=3)
> [ 192.828372] wlan0: associated
> [ 192.828515] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
> [ 192.828713] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
> [ 193.853664] wlan0: moving STA b8:c7:5d:0c:39:87 to state 3
> [ 278.421399] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 165
> [ 278.423946] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 12 WrPtr: 165
> [ 278.424007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 12 on FIFO 1
> [ 278.424835] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:87 tid = 0
> [ 285.176431] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 12 ac 2 stop
> count 1. Queue is full
> [ 290.304163] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> 397, next_recl = 174
>
>
> At this point I unloaded, and reloaded the module.
> I had to do this several times until it finally came back up.
>
> Shortly afterwards..
>
> [ 599.752969] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [ 599.755359] wlan0: authenticated
> [ 599.762131] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop
> count 1. Tx on passive channel
Interesting. The FW is complaining that you are Txing on a channel that is defined as passive channel...
> [ 599.774132] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[0] stopped
> [ 599.774551] iwlwifi 0000:04:00.0: U iwl_wake_queue Wake hwq 0 ac 0.
> Disassoc: flush queue
> [ 599.774921] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[1] awake
> [ 599.775779] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[2] awake
> [ 599.776515] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[3] awake
> [ 599.777198] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop
> count 1. Tx on passive channel
Again.
There are a few AMPDUs issues here but I guess the worst issue you are seeing is due to the passive channel thing.
Does it feel better with 11n disabled ?
---------------------------------------------------------------------
Intel Israel (74) Limited
This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.
On Tue, Jan 10, 2012 at 08:40:32PM +0000, Grumbach, Emmanuel wrote:
> Hi,
>
> Is that series I added a debug flag that tells us what happens with the queues: please enable the 31st bit: 0x80000000
>
> Just debug=0x80000000 as a module parameter.
>From boot to first hang..
[ 24.874236] Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree:d
[ 24.875980] Copyright(c) 2003-2011 Intel Corporation
[ 24.877877] iwlwifi 0000:04:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[ 24.879733] iwlwifi 0000:04:00.0: setting latency timer to 64
[ 24.879847] iwlwifi 0000:04:00.0: pci_resource_len = 0x00002000
[ 24.881528] iwlwifi 0000:04:00.0: pci_resource_base = ffffc9001155c000
[ 24.883276] iwlwifi 0000:04:00.0: HW Revision ID = 0x0
[ 24.885297] iwlwifi 0000:04:00.0: irq 46 for MSI/MSI-X
[ 24.885766] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUG enabled
[ 24.887414] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUGFS enabled
[ 24.889060] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TRACING enabled
[ 24.890740] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TESTMODE enabled
[ 24.892371] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_P2P disabled
[ 24.893963] iwlwifi 0000:04:00.0: Detected Intel(R) Ultimate N WiFi Link 5300 AGN, REV=0x24
[ 24.896234] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[ 24.919869] iwlwifi 0000:04:00.0: device EEPROM VER=0x120, CALIB=0x4
[ 24.921403] iwlwifi 0000:04:00.0: Device SKU: 0xF0
[ 24.922924] iwlwifi 0000:04:00.0: Tunable channels: 13 802.11bg, 24 802.11a channels
[ 24.943679] iwlwifi 0000:04:00.0: loaded firmware version 8.83.5.1 build 33692
[ 24.946313] Registered led device: phy0-led
[ 24.978763] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
[ 25.032235] cfg80211: Calling CRDA for country: US
[ 25.083063] cfg80211: Regulatory domain changed to country: US
[ 25.084776] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[ 25.086556] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[ 25.088280] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
[ 25.089954] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 25.091618] cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 25.093234] cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 25.095115] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
[ 36.649871] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[ 36.662470] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
[ 36.825012] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4 WrPtr: 0
[ 36.825012] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 0 on FIFO 3
[ 36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 1 on FIFO 2
[ 36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 2 on FIFO 1
[ 36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 3 on FIFO 0
[ 36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 4 on FIFO 7
[ 37.023008] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[ 37.033727] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
[ 37.215009] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4 WrPtr: 0
[ 37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 0 on FIFO 3
[ 37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 1 on FIFO 2
[ 37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 2 on FIFO 1
[ 37.222439] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 3 on FIFO 0
[ 37.222439] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 4 on FIFO 7
[ 37.321187] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[ 44.614100] wlan0: authenticate with b8:c7:5d:0c:39:88 (try 1)
[ 44.815110] wlan0: authenticate with b8:c7:5d:0c:39:88 (try 2)
[ 44.817695] wlan0: authenticated
[ 44.839289] wlan0: associate with b8:c7:5d:0c:39:88 (try 1)
[ 44.842270] wlan0: RX AssocResp from b8:c7:5d:0c:39:88 (capab=0x511 status=0 aid=3)
[ 44.842270] wlan0: associated
[ 44.842270] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
[ 44.842270] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
[ 44.862870] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[ 44.866222] cfg80211: Calling CRDA for country: US
[ 44.869918] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop count 1. Tx on passive channel
[ 44.904744] cfg80211: Regulatory domain changed to country: US
[ 44.905049] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[ 44.905435] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[ 44.905788] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
[ 44.906167] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 44.906524] cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 44.906879] cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 44.907312] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
[ 44.937401] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue Status: Q[0] stopped
[ 44.937789] iwlwifi 0000:04:00.0: I iwl_wake_queue Wake hwq 0 ac 0. channel got active
[ 44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue Status: Q[1] awake
[ 44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue Status: Q[2] awake
[ 44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue Status: Q[3] awake
[ 45.891438] wlan0: moving STA b8:c7:5d:0c:39:88 to state 3
[ 56.018088] wlan0: no IPv6 routers present
[ 97.157673] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 137
[ 97.159663] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 137
[ 97.159932] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[ 97.160516] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:88 tid = 0
[ 111.136741] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn = next_recl = 194
[ 111.137162] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 0
[ 111.137531] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Deactivate AC/CMD Queue 11 on FIFO 0
[ 147.455293] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 264
[ 147.456993] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 8
[ 147.457027] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[ 147.457830] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:88 tid = 0
[ 164.513842] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn = next_recl = 816
[ 164.514282] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 0
[ 164.514664] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Deactivate AC/CMD Queue 11 on FIFO 0
[ 173.145695] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 869
[ 173.147133] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 101
[ 173.147545] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[ 173.148050] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:88 tid = 0
[ 192.805102] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[ 192.807392] wlan0: authenticated
[ 192.814840] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn 1633, next_recl = 139
[ 192.818669] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
[ 192.818939] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
[ 192.819206] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
[ 192.824157] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
[ 192.828014] wlan0: RX ReassocResp from b8:c7:5d:0c:39:87 (capab=0x431 status=0 aid=3)
[ 192.828372] wlan0: associated
[ 192.828515] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
[ 192.828713] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
[ 193.853664] wlan0: moving STA b8:c7:5d:0c:39:87 to state 3
[ 278.421399] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 165
[ 278.423946] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 12 WrPtr: 165
[ 278.424007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 12 on FIFO 1
[ 278.424835] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:87 tid = 0
[ 285.176431] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 12 ac 2 stop count 1. Queue is full
[ 290.304163] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn 397, next_recl = 174
At this point I unloaded, and reloaded the module.
I had to do this several times until it finally came back up.
Shortly afterwards..
[ 599.752969] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[ 599.755359] wlan0: authenticated
[ 599.762131] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop count 1. Tx on passive channel
[ 599.774132] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue Status: Q[0] stopped
[ 599.774551] iwlwifi 0000:04:00.0: U iwl_wake_queue Wake hwq 0 ac 0. Disassoc: flush queue
[ 599.774921] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue Status: Q[1] awake
[ 599.775779] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue Status: Q[2] awake
[ 599.776515] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue Status: Q[3] awake
[ 599.777198] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop count 1. Tx on passive channel
[ 599.782692] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
[ 599.782964] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
[ 599.783538] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
[ 599.790449] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
[ 599.990029] wlan0: associate with b8:c7:5d:0c:39:87 (try 2)
[ 600.190028] wlan0: associate with b8:c7:5d:0c:39:87 (try 3)
[ 600.390029] wlan0: association with b8:c7:5d:0c:39:87 timed out
[ 608.005916] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[ 608.206036] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
[ 608.406036] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
[ 608.607032] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
[ 616.193769] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[ 616.394070] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
[ 616.594039] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
[ 616.794053] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
[ 619.373114] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[ 619.573124] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
[ 619.773146] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
[ 619.973146] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
[ 627.666387] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[ 627.866077] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
[ 628.066146] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
[ 628.266121] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
[ 635.854105] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[ 636.054043] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
[ 636.254134] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
[ 636.454125] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
and dead again.
Dave
>
> Ok, here's a fresh log.
>
> wireless was working, (with 11n_disable=1)
>
> unload, and reload without the 11n_disable=1 ..
>
> [16421.730025] wlan0: deauthenticating from b8:c7:5d:0c:39:87 by local choice
> (reason=3)
> [16421.735002] ieee80211 phy0: failed to remove key (1, ff:ff:ff:ff:ff:ff)
> from hardware (-16)
> [16421.736095] ieee80211 phy0: failed to remove key (2, ff:ff:ff:ff:ff:ff)
> from hardware (-16)
> [16421.737548] ieee80211 phy0: failed to remove key (0, b8:c7:5d:0c:39:87)
> from hardware (-16)
> [16421.738400] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
> [16421.738646] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
> [16421.738878] wlan0: moving STA b8:c7:5d:0c:39:87 to state 0
> [16421.741175] cfg80211: Calling CRDA to update world regulatory domain
> [16421.777981] iwlwifi 0000:04:00.0: PCI INT A disabled
> [16421.803665] cfg80211: World regulatory domain updated:
> [16421.803924] cfg80211: (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [16421.808846] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16421.811357] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi,
> 2000 mBm)
> [16421.811739] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi,
> 2000 mBm)
> [16421.812193] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16421.812566] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16421.820504] cfg80211: Calling CRDA for country: US
> [16421.918341] cfg80211: Calling CRDA to update world regulatory domain
> [16421.949295] cfg80211: World regulatory domain updated:
> [16421.949559] cfg80211: (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [16421.949966] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16421.950851] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi,
> 2000 mBm)
> [16421.951528] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi,
> 2000 mBm)
> [16421.951911] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16421.952651] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16422.035828] Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree:d
> [16422.036165] Copyright(c) 2003-2011 Intel Corporation
> [16422.036582] iwlwifi 0000:04:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ
> 17
> [16422.036957] iwlwifi 0000:04:00.0: setting latency timer to 64
> [16422.037338] iwlwifi 0000:04:00.0: pci_resource_len = 0x00002000
> [16422.037620] iwlwifi 0000:04:00.0: pci_resource_base = ffffc90011560000
> [16422.037930] iwlwifi 0000:04:00.0: HW Revision ID = 0x0
> [16422.038381] iwlwifi 0000:04:00.0: irq 46 for MSI/MSI-X
> [16422.038915] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUG enabled
> [16422.041287] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUGFS enabled
> [16422.041569] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TRACING enabled
> [16422.041881] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TESTMODE enabled
> [16422.042213] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_P2P disabled
> [16422.042517] iwlwifi 0000:04:00.0: Detected Intel(R) Ultimate N WiFi Link
> 5300 AGN, REV=0x24
> [16422.043276] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [16422.075500] iwlwifi 0000:04:00.0: device EEPROM VER=0x120, CALIB=0x4
> [16422.075809] iwlwifi 0000:04:00.0: Device SKU: 0xF0
> [16422.076390] iwlwifi 0000:04:00.0: Tunable channels: 13 802.11bg, 24 802.11a
> channels
> [16422.121284] iwlwifi 0000:04:00.0: loaded firmware version 8.83.5.1 build
> 33692
> [16422.122291] Registered led device: phy0-led
> [16422.124681] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
> [16422.155786] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [16422.159119] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4 WrPtr: 0
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 0 on FIFO 3
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 1 on FIFO 2
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 2 on FIFO 1
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 3 on FIFO 0
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 4 on FIFO 7
> [16422.263369] cfg80211: Calling CRDA for country: US
> [16422.287176] cfg80211: Regulatory domain changed to country: US
> [16422.287457] cfg80211: (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [16422.287849] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2700 mBm)
> [16422.288337] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 1700 mBm)
> [16422.288703] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16422.289090] cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16422.289455] cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16422.289824] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 3000 mBm)
> [16422.318523] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [16422.321880] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4 WrPtr: 0
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 0 on FIFO 3
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 1 on FIFO 2
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 2 on FIFO 1
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 3 on FIFO 0
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 4 on FIFO 7
> [16422.376787] ADDRCONF(NETDEV_UP): wlan0: link is not ready
> [16427.671916] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [16427.674716] wlan0: authenticated
> [16427.678205] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
> [16427.681953] wlan0: RX AssocResp from b8:c7:5d:0c:39:87 (capab=0x431
> status=0 aid=3)
> [16427.682325] wlan0: associated
> [16427.682473] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
> [16427.682731] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
> [16427.700757] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
> [16427.701667] cfg80211: Calling CRDA for country: US
> [16427.721184] cfg80211: Regulatory domain changed to country: US
> [16427.721455] cfg80211: (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [16427.721829] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2700 mBm)
> [16427.722199] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 1700 mBm)
> [16427.722566] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16427.722924] cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16427.723289] cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16427.723651] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 3000 mBm)
> [16428.706438] wlan0: moving STA b8:c7:5d:0c:39:87 to state 3
> [16438.802048] wlan0: no IPv6 routers present
>
> wifi is back up.
>
> Shortly afterwards ..
>
>
> [16520.224964] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 124
> [16520.228038] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 124
> [16520.228358] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [16520.229059] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:87 tid = 0
> [16531.888296] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
> next_recl = 631
> [16531.888793] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 0
> [16531.889247] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
> Deactivate AC/CMD Queue 11 on FIFO 0
> [16552.504609] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 697
> [16552.508182] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 185
> [16552.508609] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [16552.509077] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:87 tid = 0
> [16564.084058] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
> next_recl = 1241
> [16564.084506] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 0
> [16564.084903] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
> Deactivate AC/CMD Queue 11 on FIFO 0
> [16568.975872] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 1298
> [16568.978796] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 18
> [16568.979007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [16568.979734] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:87 tid = 0
> [16580.004052] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> 1491, next_recl = 150
>
I understand there is nothing afterwards... This is really weird. The sequence numbers here are really crazy...
I need to think that over.
>
> A possibly interesting datapoint, is that it seems I can make this happen
> faster
> if there's disk IO going on (I ran a make clean on a kernel tree in this
> case).
> Might be entirely coincidental, but thought I'd mention it..
>
Ok, thanks for the info.
---------------------------------------------------------------------
Intel Israel (74) Limited
This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.
On Wed, Jan 11, 2012 at 12:38:43PM +0000, Grumbach, Emmanuel wrote:
> > [ 173.145695] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> > next_recl = 869
> > [ 173.147133] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 101
> > [ 173.147545] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> > BA Queue 11 on FIFO 1
> > [ 173.148050] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> > b8:c7:5d:0c:39:88 tid = 0
>
> I am missing logs here... You seem to reauthenticate but I can't see disconnection... weird
I'll recreate some clean logs in a few minutes..
> > [ 192.805102] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> > [ 192.807392] wlan0: authenticated
> > [ 192.814840] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> > 1633, next_recl = 139
>
> Stop AGG before we are associated ?!
> Is that leftovers from the previous association that was torn down ?
no idea.
> > [ 192.818669] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
> > [ 192.818939] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
> > [ 192.819206] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
> > [ 192.824157] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
>
> Associating to another AP ? A band maybe ?
I only have one AP.
> There are a few AMPDUs issues here but I guess the worst issue you are seeing is due to the passive channel thing.
> Does it feel better with 11n disabled ?
5 hours of use this morning with 11n_disabled=1, and not a single problem.
I'll re-enable 11n, and get you some cleaner logs shortly.
Dave
> From boot to first hang..
>
> [ 24.874236] Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree:d
> [ 24.875980] Copyright(c) 2003-2011 Intel Corporation
> [ 24.877877] iwlwifi 0000:04:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ
> 17
> [ 24.879733] iwlwifi 0000:04:00.0: setting latency timer to 64
> [ 24.879847] iwlwifi 0000:04:00.0: pci_resource_len = 0x00002000
> [ 24.881528] iwlwifi 0000:04:00.0: pci_resource_base = ffffc9001155c000
> [ 24.883276] iwlwifi 0000:04:00.0: HW Revision ID = 0x0
> [ 24.885297] iwlwifi 0000:04:00.0: irq 46 for MSI/MSI-X
> [ 24.885766] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUG enabled
> [ 24.887414] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUGFS enabled
> [ 24.889060] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TRACING enabled
> [ 24.890740] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TESTMODE enabled
> [ 24.892371] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_P2P disabled
> [ 24.893963] iwlwifi 0000:04:00.0: Detected Intel(R) Ultimate N WiFi Link
> 5300 AGN, REV=0x24
> [ 24.896234] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [ 24.919869] iwlwifi 0000:04:00.0: device EEPROM VER=0x120, CALIB=0x4
> [ 24.921403] iwlwifi 0000:04:00.0: Device SKU: 0xF0
> [ 24.922924] iwlwifi 0000:04:00.0: Tunable channels: 13 802.11bg, 24 802.11a
> channels
> [ 24.943679] iwlwifi 0000:04:00.0: loaded firmware version 8.83.5.1 build
> 33692
> [ 24.946313] Registered led device: phy0-led
> [ 24.978763] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
> [ 25.032235] cfg80211: Calling CRDA for country: US
> [ 25.083063] cfg80211: Regulatory domain changed to country: US
> [ 25.084776] cfg80211: (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [ 25.086556] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2700 mBm)
> [ 25.088280] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 1700 mBm)
> [ 25.089954] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [ 25.091618] cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [ 25.093234] cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [ 25.095115] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 3000 mBm)
>
> [ 36.649871] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [ 36.662470] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
> [ 36.825012] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4 WrPtr: 0
> [ 36.825012] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 0 on FIFO 3
> [ 36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 1 on FIFO 2
> [ 36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 2 on FIFO 1
> [ 36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 3 on FIFO 0
> [ 36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 4 on FIFO 7
> [ 37.023008] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [ 37.033727] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
> [ 37.215009] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4 WrPtr: 0
> [ 37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 0 on FIFO 3
> [ 37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 1 on FIFO 2
> [ 37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 2 on FIFO 1
> [ 37.222439] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 3 on FIFO 0
> [ 37.222439] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 4 on FIFO 7
> [ 37.321187] ADDRCONF(NETDEV_UP): wlan0: link is not ready
> [ 44.614100] wlan0: authenticate with b8:c7:5d:0c:39:88 (try 1)
> [ 44.815110] wlan0: authenticate with b8:c7:5d:0c:39:88 (try 2)
> [ 44.817695] wlan0: authenticated
> [ 44.839289] wlan0: associate with b8:c7:5d:0c:39:88 (try 1)
> [ 44.842270] wlan0: RX AssocResp from b8:c7:5d:0c:39:88 (capab=0x511
> status=0 aid=3)
> [ 44.842270] wlan0: associated
> [ 44.842270] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
> [ 44.842270] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
> [ 44.862870] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
> [ 44.866222] cfg80211: Calling CRDA for country: US
> [ 44.869918] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop
> count 1. Tx on passive channel
> [ 44.904744] cfg80211: Regulatory domain changed to country: US
> [ 44.905049] cfg80211: (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [ 44.905435] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2700 mBm)
> [ 44.905788] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 1700 mBm)
> [ 44.906167] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [ 44.906524] cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [ 44.906879] cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [ 44.907312] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 3000 mBm)
> [ 44.937401] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue
> Status: Q[0] stopped
> [ 44.937789] iwlwifi 0000:04:00.0: I iwl_wake_queue Wake hwq 0 ac 0. channel
> got active
> [ 44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue
> Status: Q[1] awake
> [ 44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue
> Status: Q[2] awake
> [ 44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue
> Status: Q[3] awake
> [ 45.891438] wlan0: moving STA b8:c7:5d:0c:39:88 to state 3
> [ 56.018088] wlan0: no IPv6 routers present
> [ 97.157673] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 137
> [ 97.159663] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 137
> [ 97.159932] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [ 97.160516] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:88 tid = 0
> [ 111.136741] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
> next_recl = 194
> [ 111.137162] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 0
> [ 111.137531] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
> Deactivate AC/CMD Queue 11 on FIFO 0
>
> [ 147.455293] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 264
> [ 147.456993] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 8
> [ 147.457027] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [ 147.457830] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:88 tid = 0
> [ 164.513842] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
> next_recl = 816
> [ 164.514282] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 0
> [ 164.514664] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
> Deactivate AC/CMD Queue 11 on FIFO 0
> [ 173.145695] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 869
> [ 173.147133] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 101
> [ 173.147545] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [ 173.148050] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:88 tid = 0
> [ 192.805102] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [ 192.807392] wlan0: authenticated
> [ 192.814840] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> 1633, next_recl = 139
> [ 192.818669] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
> [ 192.818939] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
> [ 192.819206] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
> [ 192.824157] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
> [ 192.828014] wlan0: RX ReassocResp from b8:c7:5d:0c:39:87 (capab=0x431
> status=0 aid=3)
> [ 192.828372] wlan0: associated
> [ 192.828515] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
> [ 192.828713] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
> [ 193.853664] wlan0: moving STA b8:c7:5d:0c:39:87 to state 3
> [ 278.421399] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 165
> [ 278.423946] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 12 WrPtr: 165
> [ 278.424007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 12 on FIFO 1
> [ 278.424835] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:87 tid = 0
> [ 285.176431] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 12 ac 2 stop
> count 1. Queue is full
> [ 290.304163] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> 397, next_recl = 174
>
>
> At this point I unloaded, and reloaded the module.
> I had to do this several times until it finally came back up.
>
> Shortly afterwards..
>
> [ 599.752969] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [ 599.755359] wlan0: authenticated
> [ 599.762131] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop
> count 1. Tx on passive channel
> [ 599.774132] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[0] stopped
> [ 599.774551] iwlwifi 0000:04:00.0: U iwl_wake_queue Wake hwq 0 ac 0.
> Disassoc: flush queue
> [ 599.774921] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[1] awake
> [ 599.775779] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[2] awake
> [ 599.776515] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[3] awake
> [ 599.777198] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop
> count 1. Tx on passive channel
> [ 599.782692] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
> [ 599.782964] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
> [ 599.783538] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
> [ 599.790449] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
> [ 599.990029] wlan0: associate with b8:c7:5d:0c:39:87 (try 2)
> [ 600.190028] wlan0: associate with b8:c7:5d:0c:39:87 (try 3)
> [ 600.390029] wlan0: association with b8:c7:5d:0c:39:87 timed out
> [ 608.005916] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [ 608.206036] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
> [ 608.406036] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
> [ 608.607032] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
> [ 616.193769] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [ 616.394070] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
> [ 616.594039] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
> [ 616.794053] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
> [ 619.373114] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [ 619.573124] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
> [ 619.773146] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
> [ 619.973146] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
> [ 627.666387] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [ 627.866077] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
> [ 628.066146] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
> [ 628.266121] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
> [ 635.854105] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [ 636.054043] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
> [ 636.254134] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
> [ 636.454125] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
>
Ok, I see several issues. Will get back to you
In the meantime: disable11n=1 will help (not sure it is the correct syntax, check out the modinfo please. I am in a hurry now :-))
---------------------------------------------------------------------
Intel Israel (74) Limited
This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.
>>
>> [16520.224964] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
>> next_recl = 124
>> [16520.228038] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 ?WrPtr: 124
>> [16520.228358] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
>> BA Queue 11 on FIFO 1
>> [16520.229059] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
>> b8:c7:5d:0c:39:87 tid = 0
>> [16531.888296] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
>> next_recl = 631
>> [16531.888793] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 ?WrPtr: 0
>> [16531.889247] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
>> Deactivate AC/CMD Queue 11 on FIFO 0
>> [16552.504609] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
>> next_recl = 697
>> [16552.508182] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 ?WrPtr: 185
>> [16552.508609] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
>> BA Queue 11 on FIFO 1
>> [16552.509077] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
>> b8:c7:5d:0c:39:87 tid = 0
>> [16564.084058] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
>> next_recl = 1241
>> [16564.084506] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 ?WrPtr: 0
>> [16564.084903] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
>> Deactivate AC/CMD Queue 11 on FIFO 0
>> [16568.975872] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
>> next_recl = 1298
>> [16568.978796] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 ?WrPtr: 18
>> [16568.979007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
>> BA Queue 11 on FIFO 1
>> [16568.979734] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
>> b8:c7:5d:0c:39:87 tid = 0
>> [16580.004052] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
>> 1491, next_recl = 150
>>
>
> I understand there is nothing afterwards... This is really weird. The sequence numbers here are really crazy...
> I need to think that over.
>
>>
Ok, I finally had a change to take a closer look at this. Please run
with debug=0xC0000000.
This will be noisy, but I guess we have no choice...
I will be travelling next week, so...
On Thu, Jan 19, 2012 at 08:47:28AM +0200, Emmanuel Grumbach wrote:
> Ok, I finally had a change to take a closer look at this. Please run
> with debug=0xC0000000.
>
> This will be noisy, but I guess we have no choice...
> I will be travelling next week, so...
Ah. Got it. I had to do a large download (a kernel tarball was enough) to trigger it.
Log is at http://davej.fedorapeople.org/iwl-debug.txt
The download began at around 13:17 in the log.
It hung shortly afterwards.
Dave
>
> On Thu, Jan 19, 2012 at 08:47:28AM +0200, Emmanuel Grumbach wrote:
> > Ok, I finally had a change to take a closer look at this. Please run
> > with debug=0xC0000000.
> >
> > This will be noisy, but I guess we have no choice...
> > I will be travelling next week, so...
>
> Ah. Got it. I had to do a large download (a kernel tarball was enough) to
> trigger it.
> Log is at http://davej.fedorapeople.org/iwl-debug.txt
>
> The download began at around 13:17 in the log.
> It hung shortly afterwards.
>
> Dave
Thanks for that one. Really helpful. I need to send you a patch to get a little more data. I don't know when I will be able to do it though.
---------------------------------------------------------------------
Intel Israel (74) Limited
This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.
On Wed, Jan 11, 2012 at 12:38:43PM +0000, Grumbach, Emmanuel wrote:
> I am missing logs here... You seem to reauthenticate but I can't see disconnection... weird
Ok, here's a fresh log.
wireless was working, (with 11n_disable=1)
unload, and reload without the 11n_disable=1 ..
[16421.730025] wlan0: deauthenticating from b8:c7:5d:0c:39:87 by local choice (reason=3)
[16421.735002] ieee80211 phy0: failed to remove key (1, ff:ff:ff:ff:ff:ff) from hardware (-16)
[16421.736095] ieee80211 phy0: failed to remove key (2, ff:ff:ff:ff:ff:ff) from hardware (-16)
[16421.737548] ieee80211 phy0: failed to remove key (0, b8:c7:5d:0c:39:87) from hardware (-16)
[16421.738400] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
[16421.738646] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
[16421.738878] wlan0: moving STA b8:c7:5d:0c:39:87 to state 0
[16421.741175] cfg80211: Calling CRDA to update world regulatory domain
[16421.777981] iwlwifi 0000:04:00.0: PCI INT A disabled
[16421.803665] cfg80211: World regulatory domain updated:
[16421.803924] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[16421.808846] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16421.811357] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[16421.811739] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[16421.812193] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16421.812566] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16421.820504] cfg80211: Calling CRDA for country: US
[16421.918341] cfg80211: Calling CRDA to update world regulatory domain
[16421.949295] cfg80211: World regulatory domain updated:
[16421.949559] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[16421.949966] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16421.950851] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[16421.951528] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[16421.951911] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16421.952651] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16422.035828] Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree:d
[16422.036165] Copyright(c) 2003-2011 Intel Corporation
[16422.036582] iwlwifi 0000:04:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[16422.036957] iwlwifi 0000:04:00.0: setting latency timer to 64
[16422.037338] iwlwifi 0000:04:00.0: pci_resource_len = 0x00002000
[16422.037620] iwlwifi 0000:04:00.0: pci_resource_base = ffffc90011560000
[16422.037930] iwlwifi 0000:04:00.0: HW Revision ID = 0x0
[16422.038381] iwlwifi 0000:04:00.0: irq 46 for MSI/MSI-X
[16422.038915] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUG enabled
[16422.041287] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUGFS enabled
[16422.041569] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TRACING enabled
[16422.041881] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TESTMODE enabled
[16422.042213] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_P2P disabled
[16422.042517] iwlwifi 0000:04:00.0: Detected Intel(R) Ultimate N WiFi Link 5300 AGN, REV=0x24
[16422.043276] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[16422.075500] iwlwifi 0000:04:00.0: device EEPROM VER=0x120, CALIB=0x4
[16422.075809] iwlwifi 0000:04:00.0: Device SKU: 0xF0
[16422.076390] iwlwifi 0000:04:00.0: Tunable channels: 13 802.11bg, 24 802.11a channels
[16422.121284] iwlwifi 0000:04:00.0: loaded firmware version 8.83.5.1 build 33692
[16422.122291] Registered led device: phy0-led
[16422.124681] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
[16422.155786] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[16422.159119] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4 WrPtr: 0
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 0 on FIFO 3
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 1 on FIFO 2
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 2 on FIFO 1
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 3 on FIFO 0
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 4 on FIFO 7
[16422.263369] cfg80211: Calling CRDA for country: US
[16422.287176] cfg80211: Regulatory domain changed to country: US
[16422.287457] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[16422.287849] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[16422.288337] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
[16422.288703] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16422.289090] cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16422.289455] cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16422.289824] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
[16422.318523] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[16422.321880] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4 WrPtr: 0
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 0 on FIFO 3
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 1 on FIFO 2
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 2 on FIFO 1
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 3 on FIFO 0
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 4 on FIFO 7
[16422.376787] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[16427.671916] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[16427.674716] wlan0: authenticated
[16427.678205] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
[16427.681953] wlan0: RX AssocResp from b8:c7:5d:0c:39:87 (capab=0x431 status=0 aid=3)
[16427.682325] wlan0: associated
[16427.682473] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
[16427.682731] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
[16427.700757] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[16427.701667] cfg80211: Calling CRDA for country: US
[16427.721184] cfg80211: Regulatory domain changed to country: US
[16427.721455] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[16427.721829] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[16427.722199] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
[16427.722566] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16427.722924] cfg80211: (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16427.723289] cfg80211: (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16427.723651] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
[16428.706438] wlan0: moving STA b8:c7:5d:0c:39:87 to state 3
[16438.802048] wlan0: no IPv6 routers present
wifi is back up.
Shortly afterwards ..
[16520.224964] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 124
[16520.228038] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 124
[16520.228358] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[16520.229059] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:87 tid = 0
[16531.888296] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn = next_recl = 631
[16531.888793] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 0
[16531.889247] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Deactivate AC/CMD Queue 11 on FIFO 0
[16552.504609] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 697
[16552.508182] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 185
[16552.508609] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[16552.509077] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:87 tid = 0
[16564.084058] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn = next_recl = 1241
[16564.084506] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 0
[16564.084903] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Deactivate AC/CMD Queue 11 on FIFO 0
[16568.975872] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 1298
[16568.978796] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11 WrPtr: 18
[16568.979007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[16568.979734] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:87 tid = 0
[16580.004052] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn 1491, next_recl = 150
A possibly interesting datapoint, is that it seems I can make this happen faster
if there's disk IO going on (I ran a make clean on a kernel tree in this case).
Might be entirely coincidental, but thought I'd mention it..
Dave
On Tue, Jan 10, 2012 at 10:05:25PM +0000, Venkataraman, Meenakshi wrote:
> Hi Dan,
>
> >> For the last few releases, iwlwifi has been getting consistently worse
> >> wrt reliability for me.
>
> [MV] Do you have an approximate idea of what release the failure started occurring?
>
> The failure mode has varied, from the chip
> >> just locking up with no tx/rx of packets with nothing being logged, to
> >> microcode warnings, and spewing 'Tx aggregation enabled' messages over
> >and over.
>
> [MV] I'm not sure if it is related to the problem you're seeing, but I see that you're using a 5300, so can you try to load the iwlwifi module with the following parameter and see if it helps?
>
> modprobe iwlagn bt_coex_active=0
Seems to make no difference at all.
Dave
SGksDQoNCklzIHRoYXQgc2VyaWVzIEkgYWRkZWQgYSBkZWJ1ZyBmbGFnIHRoYXQgdGVsbHMgdXMg
d2hhdCBoYXBwZW5zIHdpdGggdGhlIHF1ZXVlczogcGxlYXNlIGVuYWJsZSB0aGUgMzFzdCBiaXQ6
IDB4ODAwMDAwMDANCg0KSnVzdCBkZWJ1Zz0weDgwMDAwMDAwIGFzIGEgbW9kdWxlIHBhcmFtZXRl
ci4NCg0KPiANCj4gT24gVHVlLCAyMDEyLTAxLTEwIGF0IDEzOjQ5IC0wNTAwLCBEYXZlIEpvbmVz
IHdyb3RlOg0KPiA+IEZvciB0aGUgbGFzdCBmZXcgcmVsZWFzZXMsIGl3bHdpZmkgaGFzIGJlZW4g
Z2V0dGluZyBjb25zaXN0ZW50bHkgd29yc2UNCj4gPiB3cnQgcmVsaWFiaWxpdHkgZm9yIG1lLiAg
VGhlIGZhaWx1cmUgbW9kZSBoYXMgdmFyaWVkLCBmcm9tIHRoZSBjaGlwIGp1c3QNCj4gPiBsb2Nr
aW5nIHVwIHdpdGggbm8gdHgvcnggb2YgcGFja2V0cyB3aXRoIG5vdGhpbmcgYmVpbmcgbG9nZ2Vk
LCB0bw0KPiA+IG1pY3JvY29kZSB3YXJuaW5ncywgYW5kIHNwZXdpbmcgJ1R4IGFnZ3JlZ2F0aW9u
IGVuYWJsZWQnIG1lc3NhZ2VzIG92ZXIgYW5kDQo+IG92ZXIuDQo+IA0KPiBZb3UgbWlnaHQgd2Fu
dCB0byBDQyBsaW51eC13aXJlbGVzc0B2Z2VyIHRvby4uLg0KPiANCj4gPiBUaGUgbWVyZ2UgcG9z
dCAzLjIgaGFzIG1hZGUgdGhlc2UgcHJvYmxlbXMgYSBsb3Qgd29yc2UuICBCZWZvcmUsIHRoZXNl
DQo+ID4gbG9jay11cHMgd2VyZSBoYXBwZW5pbmcgb25jZSBvciB0d2ljZSBhIGRheS4gTm93IHRo
ZXkgaGFwcGVuIHNldmVyYWwgdGltZXMNCj4gYW4gaG91cg0KPiA+IChhbmQgYWZ0ZXIgdGhlIGZp
cnN0IG9uZSwgdGhleSBzZWVtIG1vcmUgZnJlcXVlbnQpLiBXaGVuIHRoZXkgaGFwcGVuLA0KPiA+
IHVubG9hZGluZyBhbmQgcmVsb2FkaW5nIHRoZSBtb2R1bGUgaXMgdGhlIG9ubHkgd2F5IGZvciBt
ZSB0byBnZXQgd29ya2luZw0KPiB3aXJlbGVzcyBhZ2Fpbi4NCj4gPiBUaGV5IG1heSBoYXBwZW4g
bW9yZSBmcmVxdWVudGx5IHdoZW4gdGhlIGxhcHRvcCBpcyBub3QgaWRsZS4NCj4gPg0KPiA+IEkg
ZGlkIGEgYmlzZWN0IG9mIHRoZSBjaGFuZ2VzIHNpbmNlIDMuMiwgd2hpY2ggcG9pbnRlZCBhdA0K
PiA3NmJjMTBmY2QxMjhhZDAyOGNmNzdjNjJlMTc5Y2QyMGRjMmZmZWNmDQo+ID4gYXMgYmVpbmcg
dGhlIGN1bHByaXQsIGJ1dCB0byBiZSBob25lc3QgSSdtIG5vdCAxMDAlIGNvbnZpbmNlZC4NCj4g
Pg0KPiA+IEJlY2F1c2UgZXZlcnkgc3RlcCBvZiB0aGUgd2F5IGR1cmluZyB0aGUgYmlzZWN0LCBJ
IHNhdyBkaWZmZXJlbnQgZmFpbHVyZQ0KPiBtb2RlcywNCj4gPiBzbyB3aGVuIEkgbWFya2VkIHNv
bWV0aGluZyBhcyAnZ29vZCcsIGl0IG1lYW50ICJkb2Vzbid0IGxvY2sgdXAgaW4gdGhlIHNhbWUN
Cj4gd2F5IiwNCj4gPiBldmVuIHRob3VnaCBpdCBtYXkgYmUgc3ltcHRvbWF0aWMgb2YgdGhlIHNh
bWUgcHJvYmxlbS4NCj4gPg0KPiA+IFRoZSBzcGVjaWZpYyBjaGlwIEknbSB1c2luZyBpcyBhIDUz
MDAgaW4gYSBEZWxsIEFkYW1vLCBjb25uZWN0aW5nIHRvDQo+ID4gYW4gQXBwbGUgYWlycG9ydCBl
eHRyZW1lIChjdXJyZW50IG1vZGVsKSBpbiBOIG1vZGUuDQo+ID4NCj4gPiAJRGF2ZQ0KPiA+DQo+
ID4gLS0NCj4gPiBUbyB1bnN1YnNjcmliZSBmcm9tIHRoaXMgbGlzdDogc2VuZCB0aGUgbGluZSAi
dW5zdWJzY3JpYmUgbmV0ZGV2IiBpbg0KPiA+IHRoZSBib2R5IG9mIGEgbWVzc2FnZSB0byBtYWpv
cmRvbW9Admdlci5rZXJuZWwub3JnDQo+ID4gTW9yZSBtYWpvcmRvbW8gaW5mbyBhdCAgaHR0cDov
L3ZnZXIua2VybmVsLm9yZy9tYWpvcmRvbW8taW5mby5odG1sDQo+IA0KDQotLS0tLS0tLS0tLS0t
LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0K
SW50ZWwgSXNyYWVsICg3NCkgTGltaXRlZAoKVGhpcyBlLW1haWwgYW5kIGFueSBhdHRhY2htZW50
cyBtYXkgY29udGFpbiBjb25maWRlbnRpYWwgbWF0ZXJpYWwgZm9yCnRoZSBzb2xlIHVzZSBvZiB0
aGUgaW50ZW5kZWQgcmVjaXBpZW50KHMpLiBBbnkgcmV2aWV3IG9yIGRpc3RyaWJ1dGlvbgpieSBv
dGhlcnMgaXMgc3RyaWN0bHkgcHJvaGliaXRlZC4gSWYgeW91IGFyZSBub3QgdGhlIGludGVuZGVk
CnJlY2lwaWVudCwgcGxlYXNlIGNvbnRhY3QgdGhlIHNlbmRlciBhbmQgZGVsZXRlIGFsbCBjb3Bp
ZXMuCg==
SGkgRGFuLA0KDQo+PiBGb3IgdGhlIGxhc3QgZmV3IHJlbGVhc2VzLCBpd2x3aWZpIGhhcyBiZWVu
IGdldHRpbmcgY29uc2lzdGVudGx5IHdvcnNlDQo+PiB3cnQgcmVsaWFiaWxpdHkgZm9yIG1lLiAN
Cg0KW01WXSBEbyB5b3UgaGF2ZSBhbiBhcHByb3hpbWF0ZSBpZGVhIG9mIHdoYXQgcmVsZWFzZSB0
aGUgZmFpbHVyZSBzdGFydGVkIG9jY3VycmluZz8NCg0KIFRoZSBmYWlsdXJlIG1vZGUgaGFzIHZh
cmllZCwgZnJvbSB0aGUgY2hpcA0KPj4ganVzdCBsb2NraW5nIHVwIHdpdGggbm8gdHgvcnggb2Yg
cGFja2V0cyB3aXRoIG5vdGhpbmcgYmVpbmcgbG9nZ2VkLCB0bw0KPj4gbWljcm9jb2RlIHdhcm5p
bmdzLCBhbmQgc3Bld2luZyAnVHggYWdncmVnYXRpb24gZW5hYmxlZCcgbWVzc2FnZXMgb3Zlcg0K
PmFuZCBvdmVyLg0KIA0KW01WXSBJJ20gbm90IHN1cmUgaWYgaXQgaXMgcmVsYXRlZCB0byB0aGUg
cHJvYmxlbSB5b3UncmUgc2VlaW5nLCBidXQgSSBzZWUgdGhhdCB5b3UncmUgdXNpbmcgYSA1MzAw
LCBzbyBjYW4geW91IHRyeSB0byBsb2FkIHRoZSBpd2x3aWZpIG1vZHVsZSB3aXRoIHRoZSBmb2xs
b3dpbmcgcGFyYW1ldGVyIGFuZCBzZWUgaWYgaXQgaGVscHM/DQoNCm1vZHByb2JlIGl3bGFnbiBi
dF9jb2V4X2FjdGl2ZT0wDQoNClRoYW5rcywNCk1lZW5ha3NoaQ0K
On Thu, Jan 19, 2012 at 08:47:28AM +0200, Emmanuel Grumbach wrote:
> >> [16580.004052] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> >> 1491, next_recl = 150
> >>
> >
> > I understand there is nothing afterwards... This is really weird. The sequence numbers here are really crazy...
> > I need to think that over.
> >
> >>
>
> Ok, I finally had a change to take a closer look at this. Please run
> with debug=0xC0000000.
>
> This will be noisy, but I guess we have no choice...
It is indeed noisy, and.. I can't reproduce the problem when that's set.
Some timing related problem ?
Dave