Bug 15119

Summary: iwl_bg_scan_completed: WARN on scan complete
Product: Networking Reporter: Alex Zhavnerchik (alex.vizor)
Component: WirelessAssignee: Reinette Chatre (reinette.chatre)
Status: CLOSED CODE_FIX    
Severity: normal CC: alan, linville, reinette.chatre, rjw
Priority: P1    
Hardware: x86-64   
OS: Linux   
Kernel Version: 2.6.33-rc5 Subsystem:
Regression: Yes Bisected commit-id:
Bug Depends on:    
Bug Blocks: 14885    
Attachments: kernel and wicd logs
Fix deferred scan requests

Description Alex Zhavnerchik 2010-01-24 12:27:11 UTC
I have following warning in my kernel.log, don't really know what does this mean. If I can make my report more helpful please instruct me how to do it.

I'm not sure if this is a regression but I think in previous versions I did'n see such warnings

Jan 23 18:45:32 loki kernel: [17577.887406] ------------[ cut here ]------------
Jan 23 18:45:32 loki kernel: [17577.887415] wlan0: associate with AP 00:24:01:bc:51:09 (try 1)
Jan 23 18:45:32 loki kernel: [17577.887454] WARNING: at net/mac80211/scan.c:309 ieee80211_scan_completed+0x44/0x1e9 [mac80211]()
Jan 23 18:45:32 loki kernel: [17577.887460] Hardware name: 64608SG
Jan 23 18:45:32 loki kernel: [17577.887464] Modules linked in: snd_seq_dummy sco bridge stp bnep rfcomm l2cap vboxnetadp vboxnetflt autofs4
 acpi_cpufreq cpufreq_conservative cpufreq_userspace cpufreq_powersave cpufreq_stats uinput microcode fuse vboxdrv firewire_sbp2 loop btusb
 bluetooth snd_hda_codec_analog snd_hda_intel snd_hda_codec snd_hwdep snd_pcm_oss snd_mixer_oss snd_pcm thinkpad_acpi snd_seq_midi snd_rawm
idi arc4 snd_seq_midi_event ecb iwlagn snd_seq iwlcore mac80211 snd_timer snd_seq_device pcmcia snd cfg80211 yenta_socket rfkill rsrc_nonst
atic psmouse snd_page_alloc soundcore evdev pcmcia_core video i2c_i801 output serio_raw pcspkr joydev battery button ac processor wmi nvram
 ext4 mbcache jbd2 crc16 sd_mod crc_t10dif ide_cd_mod cdrom ata_generic ata_piix usbhid hid ide_pci_generic ahci sdhci_pci sdhci libata fir
ewire_ohci mmc_core piix uhci_hcd led_class ricoh_mmc firewire_core crc_itu_t ide_core scsi_mod ehci_hcd e1000e intel_agp thermal fan therm
al_sys nouveau ttm drm_kms_helper drm i2c_algo_bit [
Jan 23 18:45:32 loki kernel: last unloaded: scsi_wait_scan]
Jan 23 18:45:32 loki kernel: [17577.887650] Pid: 1299, comm: iwlagn Not tainted 2.6.33-rc5 #1
Jan 23 18:45:32 loki kernel: [17577.887655] Call Trace:
Jan 23 18:45:32 loki kernel: [17577.887672]  [<ffffffff8103c0e8>] warn_slowpath_common+0x77/0x8f
Jan 23 18:45:32 loki kernel: [17577.887682]  [<ffffffff8103c10f>] warn_slowpath_null+0xf/0x11
Jan 23 18:45:32 loki kernel: [17577.887702]  [<ffffffffa047c77b>] ieee80211_scan_completed+0x44/0x1e9 [mac80211]
Jan 23 18:45:32 loki kernel: [17577.887730]  [<ffffffffa04b1438>] iwl_bg_scan_completed+0x3a/0x75 [iwlcore]
Jan 23 18:45:32 loki kernel: [17577.887741]  [<ffffffff81051b0b>] worker_thread+0x1a4/0x232
Jan 23 18:45:32 loki kernel: [17577.887765]  [<ffffffffa04b13fe>] ? iwl_bg_scan_completed+0x0/0x75 [iwlcore]
Jan 23 18:45:32 loki kernel: [17577.887776]  [<ffffffff81055703>] ? autoremove_wake_function+0x0/0x34
Jan 23 18:45:32 loki kernel: [17577.887786]  [<ffffffff8102d0c7>] ? spin_unlock_irqrestore+0x9/0xb
Jan 23 18:45:32 loki kernel: [17577.887795]  [<ffffffff81051967>] ? worker_thread+0x0/0x232
Jan 23 18:45:32 loki kernel: [17577.887804]  [<ffffffff810552b7>] kthread+0x7a/0x82
Jan 23 18:45:32 loki kernel: [17577.887813]  [<ffffffff81003824>] kernel_thread_helper+0x4/0x10
Jan 23 18:45:32 loki kernel: [17577.887822]  [<ffffffff8105523d>] ? kthread+0x0/0x82
Jan 23 18:45:32 loki kernel: [17577.887829]  [<ffffffff81003820>] ? kernel_thread_helper+0x0/0x10
Jan 23 18:45:32 loki kernel: [17577.887836] ---[ end trace daa13a680bc3a113 ]---
Comment 1 Reinette Chatre 2010-01-25 21:08:45 UTC
Your report title says "iwl_bg_scan_completed: sleeping under locks" - what does the warning you copied into your description have to do with sleeping under locks?
Comment 2 Alan 2010-01-25 21:19:27 UTC
Misread the trace
Comment 3 Reinette Chatre 2010-01-25 21:33:47 UTC
A few questions:

- Are there any errors or driver log messages before this trace?
- How do you trigger this trace? Is it easy to reproduce? Do you see it often? If this is easy to reproduce, could you load driver with debugging (modprobe iwlagn debug=0x43fff)?
- Which userspace application are you using to manage your wireless connection? Could it be doing something to trigger this? Is it possible to add some debugging (with timestamps) to coordinate what the application and kernel is doing?
Comment 4 Alex Zhavnerchik 2010-01-26 09:44:42 UTC
Created attachment 24714 [details]
kernel and wicd logs
Comment 5 Alex Zhavnerchik 2010-01-26 09:45:29 UTC
Hi. 

Before this warning I see:
Jan 10 02:35:10 loki kernel: [ 1786.204947] btusb_intr_complete: hci0 urb ffff88007d3159c0 failed to resubmit (19)
Jan 10 02:35:10 loki kernel: [ 1786.204955] btusb_bulk_complete: hci0 urb ffff88007d154680 failed to resubmit (19)
Jan 10 02:35:10 loki kernel: [ 1786.205955] btusb_bulk_complete: hci0 urb ffff88007d154740 failed to resubmit (19)
Jan 10 02:35:10 loki kernel: [ 1786.206100] btusb_send_frame: hci0 urb ffff88007ba7eec0 submission failed
Jan 10 02:35:11 loki kernel: [ 1787.811400] mac80211-phy0: failed to remove key (0, 00:13:49:e1:cd:82) from hardware (-22)
Jan 10 02:35:11 loki kernel: [ 1787.811420] wlan0: deauthenticating from 00:13:49:e1:cd:82 by local choice (reason=3)
Jan 10 02:35:12 loki kernel: [ 1788.101914] ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 10 02:35:12 loki kernel: [ 1788.103128] wlan0: direct probe to AP 00:13:49:e1:cd:82 (try 1)
Jan 10 02:35:12 loki kernel: [ 1788.105746] wlan0: direct probe responded
Jan 10 02:35:12 loki kernel: [ 1788.105755] wlan0: authenticate with AP 00:13:49:e1:cd:82 (try 1)
Jan 10 02:35:12 loki kernel: [ 1788.107722] wlan0: authenticated
Jan 10 02:35:12 loki kernel: [ 1788.107758] wlan0: associate with AP 00:13:49:e1:cd:82 (try 1)
Jan 10 02:35:12 loki kernel: [ 1788.109613] wlan0: RX ReassocResp from 00:13:49:e1:cd:82 (capab=0x411 status=1 aid=0)
Jan 10 02:35:12 loki kernel: [ 1788.109620] wlan0: AP denied association (code=1)
Jan 10 02:35:12 loki kernel: [ 1788.109644] wlan0: associate with AP 00:13:49:e1:cd:82 (try 1)
Jan 10 02:35:12 loki kernel: [ 1788.111714] wlan0: RX ReassocResp from 00:13:49:e1:cd:82 (capab=0x411 status=1 aid=0)
Jan 10 02:35:12 loki kernel: [ 1788.111721] wlan0: AP denied association (code=1)
Jan 10 02:35:12 loki kernel: [ 1788.111743] wlan0: deauthenticating from 00:13:49:e1:cd:82 by local choice (reason=3)
Jan 10 02:35:12 loki kernel: [ 1788.366927] e1000e 0000:00:19.0: irq 30 for MSI/MSI-X
Jan 10 02:35:12 loki kernel: [ 1788.417406] e1000e 0000:00:19.0: irq 30 for MSI/MSI-X
Jan 10 02:35:12 loki kernel: [ 1788.417816] ADDRCONF(NETDEV_UP): eth0: link is not ready
Jan 10 02:35:12 loki kernel: [ 1788.489985] Monitor-Mwait will be used to enter C-3 state
Jan 10 02:35:12 loki kernel: [ 1788.701366] ------------[ cut here ]------------
Jan 10 02:35:12 loki kernel: [ 1788.701409] WARNING: at net/mac80211/scan.c:309 ieee80211_scan_completed+0x44/0x1e9 [mac80211]()
Jan 10 02:35:12 loki kernel: [ 1788.701415] Hardware name: 64608SG
Jan 10 02:35:12 loki kernel: [ 1788.701419] Modules linked in: sco bridge stp bnep rfcomm l2cap vboxnetadp vboxnetflt autofs4 acpi_cpufreq
cpufreq_conservative cpufreq_userspace cpufreq_powersave cpufreq_stats uinput cryptd aes_x86_64 aes_generic microcode fuse vboxdrv firewire
_sbp2 loop snd_hda_codec_analog snd_hda_intel snd_hda_codec snd_hwdep snd_pcm_oss snd_mixer_oss snd_pcm thinkpad_acpi snd_seq_midi snd_rawm
idi snd_seq_midi_event snd_seq arc4 snd_timer ecb iwlagn snd_seq_device snd pcmcia btusb iwlcore mac80211 cfg80211 video nvram bluetooth pr
ocessor i2c_i801 yenta_socket pcspkr rsrc_nonstatic output pcmcia_core wmi button joydev battery soundcore evdev snd_page_alloc rfkill psmo
use serio_raw ac ext4 mbcache jbd2 crc16 ide_cd_mod cdrom sd_mod ata_generic crc_t10dif ata_piix ide_pci_generic firewire_ohci ahci uhci_hc
d sdhci_pci sdhci piix libata ricoh_mmc firewire_core crc_itu_t mmc_core led_class ehci_hcd ide_core scsi_mod e1000e intel_agp thermal fan
thermal_sys nouveau ttm drm_kms_helper drm i2c_algo_
Jan 10 02:35:12 loki kernel: bit [last unloaded: scsi_wait_scan]
Jan 10 02:35:12 loki kernel: [ 1788.701619] Pid: 1274, comm: iwlagn Not tainted 2.6.33-rc3 #1
Jan 10 02:35:12 loki kernel: [ 1788.701624] Call Trace:
Jan 10 02:35:12 loki kernel: [ 1788.701641]  [<ffffffff8103c0cc>] warn_slowpath_common+0x77/0x8f
Jan 10 02:35:12 loki kernel: [ 1788.701651]  [<ffffffff8103c0f3>] warn_slowpath_null+0xf/0x11
Jan 10 02:35:12 loki kernel: [ 1788.701671]  [<ffffffffa042e737>] ieee80211_scan_completed+0x44/0x1e9 [mac80211]
Jan 10 02:35:12 loki kernel: [ 1788.701700]  [<ffffffffa04632b0>] iwl_bg_scan_completed+0x3a/0x75 [iwlcore]
Jan 10 02:35:12 loki kernel: [ 1788.701711]  [<ffffffff81051acb>] worker_thread+0x1a4/0x232
Jan 10 02:35:12 loki kernel: [ 1788.701737]  [<ffffffffa0463276>] ? iwl_bg_scan_completed+0x0/0x75 [iwlcore]
Jan 10 02:35:12 loki kernel: [ 1788.701748]  [<ffffffff81055683>] ? autoremove_wake_function+0x0/0x34
Jan 10 02:35:12 loki kernel: [ 1788.701759]  [<ffffffff8102d0b7>] ? spin_unlock_irqrestore+0x9/0xb
Jan 10 02:35:12 loki kernel: [ 1788.701768]  [<ffffffff81051927>] ? worker_thread+0x0/0x232
Jan 10 02:35:12 loki kernel: [ 1788.701776]  [<ffffffff81055237>] kthread+0x7a/0x82
Jan 10 02:35:12 loki kernel: [ 1788.701786]  [<ffffffff81003824>] kernel_thread_helper+0x4/0x10
Jan 10 02:35:12 loki kernel: [ 1788.701795]  [<ffffffff810551bd>] ? kthread+0x0/0x82
Jan 10 02:35:12 loki kernel: [ 1788.701803]  [<ffffffff81003820>] ? kernel_thread_helper+0x0/0x10
Jan 10 02:35:12 loki kernel: [ 1788.701809] ---[ end trace 71a2f6ddb201d12d ]---
Jan 10 02:35:12 loki kernel: [ 1788.773898] e1000e 0000:00:19.0: irq 30 for MSI/MSI-X
Jan 10 02:35:12 loki kernel: [ 1788.824499] e1000e 0000:00:19.0: irq 30 for MSI/MSI-X
Jan 10 02:35:12 loki kernel: [ 1788.825518] ADDRCONF(NETDEV_UP): eth0: link is not ready
Jan 10 02:35:13 loki kernel: [ 1789.227330] ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 10 02:35:13 loki kernel: [ 1789.545956] ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 10 02:35:14 loki kernel: [ 1789.935472] e1000e 0000:00:19.0: irq 30 for MSI/MSI-X
Jan 10 02:35:14 loki kernel: [ 1789.986350] e1000e 0000:00:19.0: irq 30 for MSI/MSI-X
Jan 10 02:35:14 loki kernel: [ 1789.987361] ADDRCONF(NETDEV_UP): eth0: link is not ready
Jan 10 11:54:45 loki kernel: [ 1791.308376] PM: Syncing filesystems ... done.
Jan 10 11:54:45 loki kernel: [ 1791.643621] Freezing user space processes ... (elapsed 0.28 seconds) done.
Jan 10 11:54:45 loki kernel: [ 1791.929117] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 10 11:54:45 loki kernel: [ 1791.940120] Suspending console(s) (use no_console_suspend to debug)

I didn't do anything to trigger this trace specifically. As I noticed most times it happened just before I do s2disk, you can see this in my log above. I'll post  log with debug bit later.

I use wicd to manage wireless. I attached all my kernel and wicd logs to this ticket.
Comment 6 Reinette Chatre 2010-01-28 23:13:01 UTC
Unfortunately the logs you provided does not contain any debugging information. This is because your driver has not been compiled with debug support. Could you please recompile with CONFIG_IWLWIFI_DEBUG and reproduce the logs?
Comment 7 Alex Zhavnerchik 2010-01-29 09:30:26 UTC
Sorry, I can't provide more info now. Something broke in my system and now
2.6.33 boots with black screen, I'll provide more info when I restore my
system

On Fri, Jan 29, 2010 at 8:44 AM, <bugzilla-daemon@bugzilla.kernel.org>wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=15119
>
>
> Reinette Chatre <reinette.chatre@intel.com> changed:
>
>           What    |Removed                     |Added
>
> ----------------------------------------------------------------------------
>              Status|NEW                         |NEEDINFO
>
>
>
>
> --
> Configure bugmail: http://bugzilla.kernel.org/userprefs.cgi?tab=email
> ------- You are receiving this mail because: -------
> You reported the bug.
>
Comment 8 Reinette Chatre 2010-02-02 18:47:05 UTC
Created attachment 24879 [details]
Fix deferred scan requests

I was able to reproduce this problem. Please test the attached patch when you can.
Thank you
Comment 9 Alex Zhavnerchik 2010-02-02 22:41:30 UTC
Sorry. I can't reproduce it last 3 days after I updated to 2.6.33-rc6, but if I'll notice this warning again - I'll try your patch. 

Thanks for attention to my report.
Comment 10 Reinette Chatre 2010-02-03 16:52:14 UTC
Johannes posted a better fix to linux-wireless. See http://thread.gmane.org/gmane.linux.kernel.wireless.general/46260

You are not able to reproduce this anymore but since we were able to reproduce the problem and create a fix I will proceed to close this bug. Please open a new bug report if you run into this issue while running with the fix.