iwlwifi: WARNING: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected

[Dominik Brodowski]

Hi!

On 5.3.0-rc6+, I get the following lockdep warning:

=
WARNING: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected
5.3.0-rc6+ #1 Tainted: GT
-
kworker/u16:1/59 [HC0[0]:SC0[2]:HE1:SE0] is trying to acquire:
9c839cff (&(&mvm_sta->lq_sta.rs_drv.pers.lock)->rlock){+.+.}, at: 
iwl_mvm_rs_rate_init+0x53/0x80

84f6e8c2 (&(&sta->rate_ctrl_lock)->rlock){+.-.}, at: 
rate_control_rate_update+0xd0/0x1f0
which would create a new lock dependency:
 (&(&sta->rate_ctrl_lock)->rlock){+.-.} -> 
(&(&mvm_sta->lq_sta.rs_drv.pers.lock)->rlock){+.+.}

 (&(&sta->rate_ctrl_lock)->rlock){+.-.}

  lock_acquire+0xb8/0x1b0
  _raw_spin_lock_bh+0x39/0x80
  rate_control_get_rate+0x10e/0x140
  ieee80211_tx_h_rate_ctrl+0x1a9/0x3f0
  ieee80211_xmit_fast+0x260/0x9d0
  __ieee80211_subif_start_xmit+0x146/0x390
  ieee80211_subif_start_xmit+0x4a/0x3c0
  dev_hard_start_xmit+0xb0/0x310
  sch_direct_xmit+0xed/0x230
  __dev_queue_xmit+0x5ef/0xc10
  ip_finish_output2+0x2f2/0x9a0
  ip_output+0x84/0x250
  __ip_queue_xmit+0x1e0/0x5e0
  __tcp_transmit_skb+0x59f/0xb70
  tcp_write_xmit+0x369/0x1110
  tcp_tsq_handler+0x4f/0xa0
  tcp_tasklet_func+0xdd/0x120
  tasklet_action_common.isra.0+0x60/0xb0
  __do_softirq+0xf0/0x478
  do_softirq_own_stack+0x2a/0x40
  do_softirq.part.0+0x4e/0x50
  __local_bh_enable_ip+0xfb/0x100
  iwl_pcie_irq_handler+0x1e9/0x7e0
  irq_thread_fn+0x20/0x60
  irq_thread+0xfa/0x1b0
  kthread+0x10a/0x140
  ret_from_fork+0x3a/0x50

 (&(&mvm_sta->lq_sta.rs_drv.pers.lock)->rlock){+.+.}

...
  lock_acquire+0xb8/0x1b0
  _raw_spin_lock+0x34/0x80
  iwl_mvm_rs_rate_init+0x53/0x80
  iwl_mvm_mac_sta_state+0x39c/0x640
  drv_sta_state+0xb2/0x7c0
  sta_info_move_state+0x196/0x280
  ieee80211_assoc_success+0x91e/0xfd0
  ieee80211_rx_mgmt_assoc_resp.cold+0x2dd/0x5f4
  ieee80211_sta_rx_queued_mgmt+0xd7/0x7d0
  ieee80211_iface_work+0x1c4/0x2f0
  process_one_work+0x234/0x580
  worker_thread+0x50/0x3b0
  kthread+0x10a/0x140
  ret_from_fork+0x3a/0x50

 Possible interrupt unsafe locking scenario:
   CPU0CPU1
   
  lock(&(&mvm_sta->lq_sta.rs_drv.pers.lock)->rlock);
   local_irq_disable();
   lock(&(&sta->rate_ctrl_lock)->rlock);
   
lock(&(&mvm_sta->lq_sta.rs_drv.pers.lock)->rlock);
  
lock(&(&sta->rate_ctrl_lock)->rlock);

6 locks held by kworker/u16:1/59:
 #0: 1e6d0995 ((wq_completion)phy0){+.+.}, at: 
process_one_work+0x1b1/0x580
 #1: 378cac4d ((work_completion)(&sdata->work)){+.+.}, at: 
process_one_work+0x1b1/0x580
 #2: ed75 (&wdev->mtx){+.+.}, at: 
ieee80211_sta_rx_queued_mgmt+0x51/0x7d0
 #3: 7f128f47 (&local->sta_mtx){+.+.}, at: 
ieee80211_rx_mgmt_beacon+0x583/0x16c0
 #4: fc24f76f (rcu_read_lock){}, at: 
rate_control_rate_update+0x44/0x1f0
 #5: 84f6e8c2 (&(&sta->rate_ctrl_lock)->rlock){+.-.}, at: 
rate_control_rate_update+0xd0/0x1f0

-> (&(&sta->rate_ctrl_lock)->rlock){+.-.} ops: 99793 {
   HARDIRQ-ON-W at:
lock_acquire+0xb8/0x1b0
_raw_spin_lock_bh+0x39/0x80
rate_control_rate_init+0xba/0x1d0
ieee80211_assoc_success+0x8bc/0xfd0
ieee80211_rx_mgmt_assoc_resp.cold+0x2dd/0x5f4
ieee80211_sta_rx_queued_mgmt+0xd7/0x7d0
ieee80211_iface_work+0x1c4/0x2f0
process_one_work+0x234/0x580
worker_thread+0x50/0x3b0
kthread+0x10a/0x140
ret_from_fork+0x3a/0x50
   IN-SOFTIRQ-W at:
lock_acquire+0xb8/0x1b0
_raw_spin_lock_bh+0x39/0x80
rate_control_get_rate+0x10e/0x140
ieee80211_tx_h_rate_ctrl+0x1a9/0x3f0
ieee80211_xmit_fast+0x260/0x9d0
__ieee80211_subif_start_xmit+0x146/0x390
ieee80211_subif_start_xmit+0x4a/0x3c0
dev_hard_start_xmit+0xb0/0x310
sch_direct_xmit+0xed/0x230
__dev_queue_xmit+0x5ef/0xc10
ip_finish_output2+0x2f2/0x9a0
ip_output+0x84/0x250
__ip_queue_xmit+0x1e0/0x5e0
__tcp_transmit_skb+0x59f/0xb70
tcp_write_xmit+0x369/0x1110
tcp_tsq_handler+0x4f/0xa0
tcp_tasklet_func+0xdd/0x120
tasklet_action_common.isra.0+0x60/0xb0
__do_softirq+0xf0/0x478
do_softirq_own_stack+0x2a/0x40
do_softirq.part.0+0x4e/0x50
__local_bh_enable_ip+0xfb/0x100
iwl_pcie_irq_handler+0x1e9/0x7e0
irq_thread_fn+0x20/0x60
irq_thread+0xfa/0x1b0
kthr

iwlwifi: Queue 16 stuck for 10000 ms - Microcode SW error detected.

[Dominik Brodowski]

Hey,

on my pretty new iwlwifi device 8086:08b1 (7260), the following error just
appeared twice in dmesg on 4.1.0-rc4+ (Linus' tree as of Saturday/Sunday
morning):

iwlwifi :02:00.0: Queue 16 stuck for 1 ms.
iwlwifi :02:00.0: Current SW read_ptr 109 write_ptr 243
iwl data: : 00 00 00 00 00 00 00 00 00 e0 ff 1f 00 00 00 00  

iwlwifi :02:00.0: FH TRBs(0) = 0x80003019
iwlwifi :02:00.0: FH TRBs(1) = 0xc011007c
iwlwifi :02:00.0: FH TRBs(2) = 0x
iwlwifi :02:00.0: FH TRBs(3) = 0x80300015
iwlwifi :02:00.0: FH TRBs(4) = 0x
iwlwifi :02:00.0: FH TRBs(5) = 0x
iwlwifi :02:00.0: FH TRBs(6) = 0x
iwlwifi :02:00.0: FH TRBs(7) = 0x007090d3
iwlwifi :02:00.0: Q 0 is active and mapped to fifo 3 ra_tid 0x [22,22]
iwlwifi :02:00.0: Q 1 is active and mapped to fifo 2 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 2 is active and mapped to fifo 1 ra_tid 0x [187,187]
iwlwifi :02:00.0: Q 3 is active and mapped to fifo 0 ra_tid 0x [10,39]
iwlwifi :02:00.0: Q 4 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 5 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 6 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 7 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 8 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 9 is active and mapped to fifo 7 ra_tid 0x [212,212]
iwlwifi :02:00.0: Q 10 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 11 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 12 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 13 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 14 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 15 is active and mapped to fifo 5 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 16 is active and mapped to fifo 1 ra_tid 0x 
[109,243]
iwlwifi :02:00.0: Q 17 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 18 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 19 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Microcode SW error detected.  Restarting 0x200.
iwlwifi :02:00.0: CSR values:
iwlwifi :02:00.0: (2nd byte of CSR_INT_COALESCING is CSR_INT_PERIODIC_REG)
iwlwifi :02:00.0:CSR_HW_IF_CONFIG_REG: 0X40489204
iwlwifi :02:00.0:  CSR_INT_COALESCING: 0X8040
iwlwifi :02:00.0: CSR_INT: 0X
iwlwifi :02:00.0:CSR_INT_MASK: 0X
iwlwifi :02:00.0:   CSR_FH_INT_STATUS: 0X
iwlwifi :02:00.0: CSR_GPIO_IN: 0X
iwlwifi :02:00.0:   CSR_RESET: 0X
iwlwifi :02:00.0:CSR_GP_CNTRL: 0X080403c5
iwlwifi :02:00.0:  CSR_HW_REV: 0X0144
iwlwifi :02:00.0:  CSR_EEPROM_REG: 0X
iwlwifi :02:00.0:   CSR_EEPROM_GP: 0X8000
iwlwifi :02:00.0:  CSR_OTP_GP_REG: 0X803a
iwlwifi :02:00.0: CSR_GIO_REG: 0X00080040
iwlwifi :02:00.0:CSR_GP_UCODE_REG: 0X
iwlwifi :02:00.0:   CSR_GP_DRIVER_REG: 0X
iwlwifi :02:00.0:   CSR_UCODE_DRV_GP1: 0X
iwlwifi :02:00.0:   CSR_UCODE_DRV_GP2: 0X
iwlwifi :02:00.0: CSR_LED_REG: 0X0060
iwlwifi :02:00.0:CSR_DRAM_INT_TBL_REG: 0X8821408e
iwlwifi :02:00.0:CSR_GIO_CHICKEN_BITS: 0X27800200
iwlwifi :02:00.0: CSR_ANA_PLL_CFG: 0Xd5d5
iwlwifi :02:00.0:  CSR_MONITOR_STATUS_REG: 0X3c08019d
iwlwifi :02:00.0:   CSR_HW_REV_WA_REG: 0X0001001a
iwlwifi :02:00.0:CSR_DBG_HPET_MEM_REG: 0X0010
iwlwifi :02:00.0: FH register values:
iwlwifi :02:00.0: FH_RSCSR_CHNL0_STTS_WPTR_REG: 0X21418b00
iwlwifi :02:00.0:FH_RSCSR_CHNL0_RBDCB_BASE_REG: 0X021418a0
iwlwifi :02:00.0:  FH_RSCSR_CHNL0_WPTR: 0X0080
iwlwifi :02:00.0: FH_MEM_RCSR_CHNL0_CONFIG_REG: 0X00801114
iwlwifi :02:00.0:  FH_MEM_RSSR_SHARED_CTRL_REG: 0X00fc
iwlwifi :02:00.0:FH_MEM_RSSR_RX_STATUS_REG: 0X0303
iwlwifi :02:00.0:FH_MEM_RSSR_RX_ENABLE_ERR_IRQ2DRV: 0X
iwlwifi :02:00.0:FH_TSSR_TX_STATUS_REG: 0X07ff0001
iwlwifi :02:00.0: FH_TSSR_TX_ERROR_REG: 0X
iwlwifi :02:00.0: Start IWL Error Log Dump:
iwlwifi :02:00.0: Status: 0x, count: 6
iwlwifi :02:00.0: Loaded firmware version: 25.24.13.0
iwlwifi :02:00.0: 0x0084 | NMI_INTERRUPT_UNKNOWN   
iwlwifi :02:00.0: 0x0230 | uPc
iwlwifi :02:00.0: 0x | branchlink1
iwlwifi 

Re: iwlwifi: Queue 16 stuck for 10000 ms - Microcode SW error detected.

[Dominik Brodowski]

On Mon, May 25, 2015 at 09:27:39PM +0300, Emmanuel Grumbach wrote:
> On Mon, May 25, 2015 at 9:10 PM, Dominik Brodowski
>  wrote:
> > Hey,
> >
> > on my pretty new iwlwifi device 8086:08b1 (7260), the following error just
> > appeared twice in dmesg on 4.1.0-rc4+ (Linus' tree as of Saturday/Sunday
> > morning):
> 
> Firmware problem. Please try to update your -13.ucode from the git
> repository 
> (https://git.kernel.org/cgit/linux/kernel/git/iwlwifi/linux-firmware.git/)

Thanks, will test.

Dominik


signature.asc
Description: Digital signature

Re: iwlwifi: Queue 16 stuck for 10000 ms - Microcode SW error detected.

[Dominik Brodowski]

On Mon, May 25, 2015 at 08:40:47PM +0200, Dominik Brodowski wrote:
> On Mon, May 25, 2015 at 09:27:39PM +0300, Emmanuel Grumbach wrote:
> > On Mon, May 25, 2015 at 9:10 PM, Dominik Brodowski
> >  wrote:
> > > Hey,
> > >
> > > on my pretty new iwlwifi device 8086:08b1 (7260), the following error just
> > > appeared twice in dmesg on 4.1.0-rc4+ (Linus' tree as of Saturday/Sunday
> > > morning):
> > 
> > Firmware problem. Please try to update your -13.ucode from the git
> > repository 
> > (https://git.kernel.org/cgit/linux/kernel/git/iwlwifi/linux-firmware.git/)
> 
> Thanks, will test.

No joy. Firmware 25.27.13.0 also is not happy at times:

iwlwifi :02:00.0: invalid BA notification: Q 16, tid 0, flow 65535
iwlwifi :02:00.0: invalid BA notification: Q 16, tid 0, flow 65535
iwlwifi :02:00.0: invalid BA notification: Q 16, tid 0, flow 65535
iwlwifi :02:00.0: Queue 2 stuck for 1 ms.
iwlwifi :02:00.0: Current SW read_ptr 36 write_ptr 67
iwl data: : 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  

iwlwifi :02:00.0: FH TRBs(0) = 0x
iwlwifi :02:00.0: FH TRBs(1) = 0xc01100b8
iwlwifi :02:00.0: FH TRBs(2) = 0x
iwlwifi :02:00.0: FH TRBs(3) = 0x8038
iwlwifi :02:00.0: FH TRBs(4) = 0x
iwlwifi :02:00.0: FH TRBs(5) = 0x
iwlwifi :02:00.0: FH TRBs(6) = 0x
iwlwifi :02:00.0: FH TRBs(7) = 0x0070904c
iwlwifi :02:00.0: Q 0 is active and mapped to fifo 3 ra_tid 0x [9,9]
iwlwifi :02:00.0: Q 1 is active and mapped to fifo 2 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 2 is active and mapped to fifo 1 ra_tid 0x [36,67]
iwlwifi :02:00.0: Q 3 is active and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 4 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 5 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 6 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 7 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 8 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 9 is active and mapped to fifo 7 ra_tid 0x [77,77]
iwlwifi :02:00.0: Q 10 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 11 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 12 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 13 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 14 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 15 is active and mapped to fifo 5 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 16 is active and mapped to fifo 1 ra_tid 0x 
[169,230]
iwlwifi :02:00.0: Q 17 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 18 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Q 19 is inactive and mapped to fifo 0 ra_tid 0x [0,0]
iwlwifi :02:00.0: Microcode SW error detected.  Restarting 0x200.
iwlwifi :02:00.0: CSR values:
iwlwifi :02:00.0: (2nd byte of CSR_INT_COALESCING is CSR_INT_PERIODIC_REG)
iwlwifi :02:00.0:CSR_HW_IF_CONFIG_REG: 0X40489204
iwlwifi :02:00.0:  CSR_INT_COALESCING: 0X8040
iwlwifi :02:00.0: CSR_INT: 0X
iwlwifi :02:00.0:CSR_INT_MASK: 0X
iwlwifi :02:00.0:   CSR_FH_INT_STATUS: 0X
iwlwifi :02:00.0: CSR_GPIO_IN: 0X
iwlwifi :02:00.0:   CSR_RESET: 0X
iwlwifi :02:00.0:CSR_GP_CNTRL: 0X080403c5
iwlwifi :02:00.0:  CSR_HW_REV: 0X0144
iwlwifi :02:00.0:  CSR_EEPROM_REG: 0X
iwlwifi :02:00.0:   CSR_EEPROM_GP: 0X8000
iwlwifi :02:00.0:  CSR_OTP_GP_REG: 0X803a
iwlwifi :02:00.0: CSR_GIO_REG: 0X00080040
iwlwifi :02:00.0:CSR_GP_UCODE_REG: 0X
iwlwifi :02:00.0:   CSR_GP_DRIVER_REG: 0X
iwlwifi :02:00.0:   CSR_UCODE_DRV_GP1: 0X
iwlwifi :02:00.0:   CSR_UCODE_DRV_GP2: 0X
iwlwifi :02:00.0: CSR_LED_REG: 0X0060
iwlwifi :02:00.0:CSR_DRAM_INT_TBL_REG: 0X8821408c
iwlwifi :02:00.0:CSR_GIO_CHICKEN_BITS: 0X27800200
iwlwifi :02:00.0: CSR_ANA_PLL_CFG: 0Xd5d5
iwlwifi :02:00.0:  CSR_MONITOR_STATUS_REG: 0X3c08019d
iwlwifi :02:00.0:   CSR_HW_REV_WA_REG: 0X0001001a
iwlwifi :02:00.0:CSR_DBG_HPET_MEM_REG: 0X0010
iwlwifi :02:00.0: FH register values:
iwlwifi :02:00.0: FH_RSCSR_CHNL0_STTS_WPTR_REG: 0X0d9f3000
iwlwifi :02:00.0:FH_RSCSR_CHNL0_RBDCB_BASE_REG: 0X00d9f2f0
iwlwifi :02:00.0: 

Re: iwlwifi: Queue 16 stuck for 10000 ms - Microcode SW error detected.

[Dominik Brodowski]

On Sun, May 31, 2015 at 09:29:22AM +0300, Emmanuel Grumbach wrote:
> >
> > No joy. Firmware 25.27.13.0 also is not happy at times:
> 
> Are you using 40Mhz or 20Mhz?

Well, at the moment (and the problem appeared again just minutes ago):

channel 1 (2412 MHz), width: 40 MHz, center1: 2422 MHz

> > iwlwifi :02:00.0: invalid BA notification: Q 16, tid 0, flow 65535
> > iwlwifi :02:00.0: invalid BA notification: Q 16, tid 0, flow 65535
> > iwlwifi :02:00.0: invalid BA notification: Q 16, tid 0, flow 65535
> > iwlwifi :02:00.0: Queue 2 stuck for 1 ms.
> > iwlwifi :02:00.0: Current SW read_ptr 36 write_ptr 67
> > iwl data: : 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  
> > 
> > iwlwifi :02:00.0: FH TRBs(0) = 0x
> > iwlwifi :02:00.0: FH TRBs(1) = 0xc01100b8
> > iwlwifi :02:00.0: FH TRBs(2) = 0x
> > iwlwifi :02:00.0: FH TRBs(3) = 0x8038
> > iwlwifi :02:00.0: FH TRBs(4) = 0x
> > iwlwifi :02:00.0: FH TRBs(5) = 0x
> > iwlwifi :02:00.0: FH TRBs(6) = 0x
> > iwlwifi :02:00.0: FH TRBs(7) = 0x0070904c
> > iwlwifi :02:00.0: Q 0 is active and mapped to fifo 3 ra_tid 0x [9,9]
> > iwlwifi :02:00.0: Q 1 is active and mapped to fifo 2 ra_tid 0x [0,0]
> > iwlwifi :02:00.0: Q 2 is active and mapped to fifo 1 ra_tid 0x 
> > [36,67]
> > iwlwifi :02:00.0: Q 3 is active and mapped to fifo 0 ra_tid 0x [0,0]
> > iwlwifi :02:00.0: Q 4 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 5 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 6 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 7 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 8 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 9 is active and mapped to fifo 7 ra_tid 0x 
> > [77,77]
> > iwlwifi :02:00.0: Q 10 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 11 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 12 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 13 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 14 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 15 is active and mapped to fifo 5 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 16 is active and mapped to fifo 1 ra_tid 0x 
> > [169,230]
> > iwlwifi :02:00.0: Q 17 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 18 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Q 19 is inactive and mapped to fifo 0 ra_tid 0x 
> > [0,0]
> > iwlwifi :02:00.0: Microcode SW error detected.  Restarting 0x200.
> > iwlwifi :02:00.0: CSR values:
> > iwlwifi :02:00.0: (2nd byte of CSR_INT_COALESCING is 
> > CSR_INT_PERIODIC_REG)
> > iwlwifi :02:00.0:CSR_HW_IF_CONFIG_REG: 0X40489204
> > iwlwifi :02:00.0:  CSR_INT_COALESCING: 0X8040
> > iwlwifi :02:00.0: CSR_INT: 0X
> > iwlwifi :02:00.0:CSR_INT_MASK: 0X
> > iwlwifi :02:00.0:   CSR_FH_INT_STATUS: 0X
> > iwlwifi :02:00.0: CSR_GPIO_IN: 0X
> > iwlwifi :02:00.0:   CSR_RESET: 0X
> > iwlwifi :02:00.0:CSR_GP_CNTRL: 0X080403c5
> > iwlwifi :02:00.0:  CSR_HW_REV: 0X0144
> > iwlwifi :02:00.0:  CSR_EEPROM_REG: 0X
> > iwlwifi :02:00.0:   CSR_EEPROM_GP: 0X8000
> > iwlwifi :02:00.0:  CSR_OTP_GP_REG: 0X803a
> > iwlwifi :02:00.0: CSR_GIO_REG: 0X00080040
> > iwlwifi :02:00.0:CSR_GP_UCODE_REG: 0X
> > iwlwifi :02:00.0:   CSR_GP_DRIVER_REG: 0X
> > iwlwifi :02:00.0:   CSR_UCODE_DRV_GP1: 0X
> > iwlwifi :02:00.0:   CSR_UCODE_DRV_GP2: 0X
> > iwlwifi :02:00.0: CSR_LED_REG: 0X0060
> > iwlwifi :02:00.0:CSR_DRAM_INT_TBL_REG: 0X8821408c
> > iwlwifi :02:00.0:CSR_GIO_CHICKEN_BITS: 0X27800200
> > iwlwifi :02:00.0: CSR_ANA_PLL_CFG: 0Xd5d5
> > iwlwifi :02:00.0:  CSR_MONITOR_STATUS_REG: 0X3c08019d
> > iwlwifi :02:00.0:   CSR_HW_REV_WA_REG: 0X0001001a
> > iwlwifi :02:00.0:CSR_DBG_HPET_MEM_REG: 0X0010
> > iwlwifi :02:00.0: FH register values:
> > iwlwifi :02:00.0: FH_RSCSR_CHNL0_STTS_WPTR_REG: 0X0d9f3000
> > iwlwifi :02:00.0:FH_RSCSR_CHNL0_RBDCB_BASE_REG: 0X00d9f2f0
> > iwlwifi :02:00.0:  FH_RSCSR_CHNL0_WPTR: 0X00e0
> > iwlwifi :02:00.0: FH_MEM_RCSR_CHNL0_

Re: iwlwifi: Queue 16 stuck for 10000 ms - Microcode SW error detected.

[Dominik Brodowski]

On Sun, May 31, 2015 at 12:37:19PM +0300, Emmanuel Grumbach wrote:
> On Sun, May 31, 2015 at 9:52 AM, Dominik Brodowski
>  wrote:
> > On Sun, May 31, 2015 at 09:29:22AM +0300, Emmanuel Grumbach wrote:
> >> >
> >> > No joy. Firmware 25.27.13.0 also is not happy at times:
> >>
> >> Are you using 40Mhz or 20Mhz?
> >
> > Well, at the moment (and the problem appeared again just minutes ago):
> >
> > channel 1 (2412 MHz), width: 40 MHz, center1: 2422 MHz
> >
> 
> can you try to move to 20Mhz just to see if you still have the same problem?
> You can load cfg80211 with cfg80211_disable_40mhz_24ghz set to true if
> you don't want to play with the settings of your AP.

On 20MHz, I do not see the queue issue, but the "Microcode SW error"
persists:

iwlwifi :02:00.0: Microcode SW error detected.  Restarting 0x200.
iwlwifi :02:00.0: CSR values:
iwlwifi :02:00.0: (2nd byte of CSR_INT_COALESCING is
CSR_INT_PERIODIC_REG)
iwlwifi :02:00.0:CSR_HW_IF_CONFIG_REG: 0X40489204
iwlwifi :02:00.0:  CSR_INT_COALESCING: 0X8040
iwlwifi :02:00.0: CSR_INT: 0X
iwlwifi :02:00.0:CSR_INT_MASK: 0X
iwlwifi :02:00.0:   CSR_FH_INT_STATUS: 0X
iwlwifi :02:00.0: CSR_GPIO_IN: 0X
iwlwifi :02:00.0:   CSR_RESET: 0X
iwlwifi :02:00.0:CSR_GP_CNTRL: 0X080403c5
iwlwifi :02:00.0:  CSR_HW_REV: 0X0144
iwlwifi :02:00.0:  CSR_EEPROM_REG: 0X
iwlwifi :02:00.0:   CSR_EEPROM_GP: 0X8000
iwlwifi :02:00.0:  CSR_OTP_GP_REG: 0X803a
iwlwifi :02:00.0: CSR_GIO_REG: 0X00080040
iwlwifi :02:00.0:CSR_GP_UCODE_REG: 0X
iwlwifi :02:00.0:   CSR_GP_DRIVER_REG: 0X
iwlwifi :02:00.0:   CSR_UCODE_DRV_GP1: 0X
iwlwifi :02:00.0:   CSR_UCODE_DRV_GP2: 0X
iwlwifi :02:00.0: CSR_LED_REG: 0X0060
iwlwifi :02:00.0:CSR_DRAM_INT_TBL_REG: 0X88215528
iwlwifi :02:00.0:CSR_GIO_CHICKEN_BITS: 0X27800200
iwlwifi :02:00.0: CSR_ANA_PLL_CFG: 0Xd5d5
iwlwifi :02:00.0:  CSR_MONITOR_STATUS_REG: 0X3c08019d
iwlwifi :02:00.0:   CSR_HW_REV_WA_REG: 0X0001001a
iwlwifi :02:00.0:CSR_DBG_HPET_MEM_REG: 0X0010
iwlwifi :02:00.0: FH register values:
iwlwifi :02:00.0: FH_RSCSR_CHNL0_STTS_WPTR_REG: 0X2140f900
iwlwifi :02:00.0:FH_RSCSR_CHNL0_RBDCB_BASE_REG: 0X02140f80
iwlwifi :02:00.0:  FH_RSCSR_CHNL0_WPTR: 0X0048
iwlwifi :02:00.0: FH_MEM_RCSR_CHNL0_CONFIG_REG: 0X00801114
iwlwifi :02:00.0:  FH_MEM_RSSR_SHARED_CTRL_REG: 0X00fc
iwlwifi :02:00.0:FH_MEM_RSSR_RX_STATUS_REG: 0X0203
iwlwifi :02:00.0:FH_MEM_RSSR_RX_ENABLE_ERR_IRQ2DRV: 0X
iwlwifi :02:00.0:FH_TSSR_TX_STATUS_REG: 0X07ff0001
iwlwifi :02:00.0: FH_TSSR_TX_ERROR_REG: 0X
iwlwifi :02:00.0: Start IWL Error Log Dump:
iwlwifi :02:00.0: Status: 0x, count: 6
iwlwifi :02:00.0: Loaded firmware version: 25.27.13.0
iwlwifi :02:00.0: 0x0034 | NMI_INTERRUPT_WDG   
iwlwifi :02:00.0: 0x00E3 | uPc
iwlwifi :02:00.0: 0x | branchlink1
iwlwifi :02:00.0: 0x0B2E | branchlink2
iwlwifi :02:00.0: 0x00016218 | interruptlink1
iwlwifi :02:00.0: 0x82F2 | interruptlink2
iwlwifi :02:00.0: 0x | data1
iwlwifi :02:00.0: 0x0002 | data2
iwlwifi :02:00.0: 0x02039842 | data3
iwlwifi :02:00.0: 0xF300076B | beacon time
iwlwifi :02:00.0: 0x5DEB98B6 | tsf low
iwlwifi :02:00.0: 0x0002 | tsf hi
iwlwifi :02:00.0: 0x | time gp1
iwlwifi :02:00.0: 0x78E966A4 | time gp2
iwlwifi :02:00.0: 0x | time gp3
iwlwifi :02:00.0: 0x0004191B | uCode version
iwlwifi :02:00.0: 0x0144 | hw version
iwlwifi :02:00.0: 0x40489204 | board version
iwlwifi :02:00.0: 0x001C | hcmd
iwlwifi :02:00.0: 0x26F63002 | isr0
iwlwifi :02:00.0: 0x11806000 | isr1
iwlwifi :02:00.0: 0x001A | isr2
iwlwifi :02:00.0: 0x40417C82 | isr3
iwlwifi :02:00.0: 0x | isr4
iwlwifi :02:00.0: 0x10804112 | isr_pref
iwlwifi :02:00.0: 0x | wait_event
iwlwifi :02:00.0: 0x4288 | l2p_control
iwlwifi :02:00.0: 0x9C22 | l2p_duration
iwlwifi :02:00.0: 0x03BF | l2p_mhvalid
iwlwifi :02:00.0: 0x00E7 | l2p_addr_match
iwlwifi :02:00.0: 0x0017 | lmpm_pmg_sel
iwlwifi :02:00.0: 0x21051936 | timestamp
iwlwifi :02:00.0: 0x1F844858 | flow_handler
ieee80211 phy0: Hardware restart was requested

Best,
Dominik


signature.asc
Description: Digital signature

[PATCH] nl80211: take RCU read lock when calling ieee80211_bss_get_ie()

[Dominik Brodowski]

As ieee80211_bss_get_ie() derefences an RCU, it needs to be called with
rcu_read_lock held.

Fixes: 44905265bc15 ("nl80211: don't expose wdev->ssid for most interfaces")
Signed-off-by: Dominik Brodowski 
---

This patch fixes the regression I reported in the last couple of weeks for
various v4.15-rcX revisions to netdev, where a "suspicious RCU usage"
showed up in net/wireless/util.c:778.

diff --git a/net/wireless/nl80211.c b/net/wireless/nl80211.c
index 2b3dbcd40e46..1eecc249fb5e 100644
--- a/net/wireless/nl80211.c
+++ b/net/wireless/nl80211.c
@@ -2618,8 +2618,10 @@ static int nl80211_send_iface(struct sk_buff *msg, u32 
portid, u32 seq, int flag
const u8 *ssid_ie;
if (!wdev->current_bss)
break;
+   rcu_read_lock();
ssid_ie = ieee80211_bss_get_ie(&wdev->current_bss->pub,
   WLAN_EID_SSID);
+   rcu_read_unlock();
if (!ssid_ie)
break;
if (nla_put(msg, NL80211_ATTR_SSID, ssid_ie[1], ssid_ie + 2))

[PATCH v2] nl80211: take RCU read lock when calling ieee80211_bss_get_ie()

[Dominik Brodowski]

As ieee80211_bss_get_ie() derefences an RCU, it needs to be called with
rcu_read_lock held.

Fixes: 44905265bc15 ("nl80211: don't expose wdev->ssid for most interfaces")
Signed-off-by: Dominik Brodowski 
---

> This uses the ssid_ie, so that doesn't really seem right? The
> protection should extend beyond the usage.

Indeed -- I had misread the code and hadn't thought of ssid_ie also needing
the protection during its lifetime. So here's a new version 2 -- which I
will only be able to test tomorrow, though...

Thanks,
Dominik

diff --git a/net/wireless/nl80211.c b/net/wireless/nl80211.c
index 2b3dbcd40e46..b53bd8db7974 100644
--- a/net/wireless/nl80211.c
+++ b/net/wireless/nl80211.c
@@ -2618,12 +2618,15 @@ static int nl80211_send_iface(struct sk_buff *msg, u32 
portid, u32 seq, int flag
const u8 *ssid_ie;
if (!wdev->current_bss)
break;
+   rcu_read_lock();
ssid_ie = ieee80211_bss_get_ie(&wdev->current_bss->pub,
   WLAN_EID_SSID);
if (!ssid_ie)
-   break;
+   goto nla_rcu_unlock;
if (nla_put(msg, NL80211_ATTR_SSID, ssid_ie[1], ssid_ie + 2))
-   goto nla_put_failure_locked;
+   goto nla_put_failure_rcu_locked;
+ nla_rcu_unlock:
+   rcu_read_unlock();
break;
}
default:
@@ -2635,6 +2638,8 @@ static int nl80211_send_iface(struct sk_buff *msg, u32 
portid, u32 seq, int flag
genlmsg_end(msg, hdr);
return 0;
 
+ nla_put_failure_rcu_locked:
+   rcu_read_unlock();
  nla_put_failure_locked:
wdev_unlock(wdev);
  nla_put_failure:

[PATCH v3] nl80211: take RCU read lock when calling ieee80211_bss_get_ie()

[Dominik Brodowski]

As ieee80211_bss_get_ie() derefences an RCU to return ssid_ie, both
the call to this function and any operation on this variable need
protection by the RCU read lock.

Fixes: 44905265bc15 ("nl80211: don't expose wdev->ssid for most interfaces")
Signed-off-by: Dominik Brodowski 
---

> but after, perhaps it's easier to just do
> 
>   if (ssid_ie &&
>   nla_put(...)
>   goto nla_put_failure_rcu_locked;
> 
> and avoid the extra label (but yeah, it's getting late)

OK, done that (and updated the commit message), and testet it.

Thanks,
Dominik

diff --git a/net/wireless/nl80211.c b/net/wireless/nl80211.c
index 2b3dbcd40e46..ed87a97fcb0b 100644
--- a/net/wireless/nl80211.c
+++ b/net/wireless/nl80211.c
@@ -2618,12 +2618,13 @@ static int nl80211_send_iface(struct sk_buff *msg, u32 
portid, u32 seq, int flag
const u8 *ssid_ie;
if (!wdev->current_bss)
break;
+   rcu_read_lock();
ssid_ie = ieee80211_bss_get_ie(&wdev->current_bss->pub,
   WLAN_EID_SSID);
-   if (!ssid_ie)
-   break;
-   if (nla_put(msg, NL80211_ATTR_SSID, ssid_ie[1], ssid_ie + 2))
-   goto nla_put_failure_locked;
+   if (ssid_ie &&
+   nla_put(msg, NL80211_ATTR_SSID, ssid_ie[1], ssid_ie + 2))
+   goto nla_put_failure_rcu_locked;
+   rcu_read_unlock();
break;
}
default:
@@ -2635,6 +2636,8 @@ static int nl80211_send_iface(struct sk_buff *msg, u32 
portid, u32 seq, int flag
genlmsg_end(msg, hdr);
return 0;
 
+ nla_put_failure_rcu_locked:
+   rcu_read_unlock();
  nla_put_failure_locked:
wdev_unlock(wdev);
  nla_put_failure: