Bug 468896

Summary: kernel-2.6.27.4-61.fc10.x86_64: endless number of "bad: scheduling from the idle thread!"
Product: [Fedora] Fedora Reporter: Tom London <selinux>
Component: kernelAssignee: Kernel Maintainer List <kernel-maint>
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: medium    
Version: rawhideCC: Billy, jmoyer, kernel-maint, lmacken, quintela, tomek, wwoods
Target Milestone: ---Keywords: Reopened
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-03-26 13:48:18 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 466414    

Description Tom London 2008-10-28 17:53:25 UTC 
Description of problem:
Oct 28 10:10:43 tlondon kernel: bad: scheduling from the idle thread!
Oct 28 10:10:43 tlondon kernel: Pid: 0, comm: swapper Not tainted 2.6.27.4-61.fc10.x86_64 #1
Oct 28 10:10:43 tlondon kernel:
Oct 28 10:10:43 tlondon kernel: Call Trace:
Oct 28 10:10:43 tlondon kernel: [<ffffffff81034491>] dequeue_task_idle+0x32/0x3f
Oct 28 10:10:43 tlondon kernel: [<ffffffff81032bd2>] dequeue_task+0xbf/0xca
Oct 28 10:10:43 tlondon kernel: [<ffffffff81032c29>] deactivate_task+0x22/0x2b
Oct 28 10:10:43 tlondon kernel: [<ffffffff813555f4>] schedule+0x1f5/0x816
Oct 28 10:10:43 tlondon kernel: [<ffffffff8105bb9f>] ? getnstimeofday+0x3a/0x96
Oct 28 10:10:43 tlondon kernel: [<ffffffff8105b30b>] ? sched_clock_tick+0x8f/0x98
Oct 28 10:10:43 tlondon kernel: [<ffffffff8105b322>] ? sched_clock_idle_wakeup_event+0xe/0x10
Oct 28 10:10:43 tlondon kernel: [<ffffffff810601f5>] ? tick_nohz_stop_idle+0x59/0x5d
Oct 28 10:10:43 tlondon kernel: [<ffffffff8100f2cd>] cpu_idle+0x106/0x10b
Oct 28 10:10:43 tlondon kernel: [<ffffffff8134463d>] rest_init+0x61/0x63
Oct 28 10:10:43 tlondon kernel:
Oct 28 10:10:43 tlondon kernel: bad: scheduling from the idle thread!

Generated enormous number of the above messages:

[root@tlondon ~]# ls -l /var/log/messages; wc /var/log/messages
-rw------- 1 root root 2074634894 2008-10-28 10:47 /var/log/messages
  29825487  227571630 2074634894 /var/log/messages
[root@tlondon ~]# 


Version-Release number of selected component (if applicable):
kernel-2.6.27.4-61.fc10.x86_64

How reproducible:


Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:
Comment 1 Billy Croan 2008-10-28 22:46:25 UTC 
Maybe this is related.  I'm seeing my disk fill up with this message repeating in /var/log/messages.  I had to stop rsyslogd to stop it from growing to completely fill up the disk.  I'm running 2.6.27.4-47.rc3.fc10.x86_64.  How can I help track this down?

Oct 28 17:25:28 One kernel: bad: scheduling from the idle thread!
Oct 28 17:25:28 One kernel: Pid: 0, comm: swapper Tainted: P          2.6.27.4-47.rc3.fc10.x86_64 #1
Oct 28 17:25:28 One kernel:
Oct 28 17:25:28 One kernel: Call Trace:
Oct 28 17:25:28 One kernel: [<ffffffff81034491>] dequeue_task_idle+0x32/0x3f
Oct 28 17:25:28 One kernel: [<ffffffff81032bd2>] dequeue_task+0xbf/0xca
Oct 28 17:25:28 One kernel: [<ffffffff81032c29>] deactivate_task+0x22/0x2b
Oct 28 17:25:28 One kernel: [<ffffffff813555e4>] schedule+0x1f5/0x816
Oct 28 17:25:28 One kernel: [<ffffffff811c05b0>] ? acpi_state_timer_broadcast+0x41/0x43
Oct 28 17:25:28 One kernel: [<ffffffff811c0c35>] ? acpi_idle_enter_bm+0x2c7/0x2e7
Oct 28 17:25:28 One kernel: [<ffffffff8100f2cd>] cpu_idle+0x106/0x10b
Oct 28 17:25:28 One kernel: [<ffffffff81351f8f>] start_secondary+0x16e/0x173
Oct 28 17:25:28 One kernel:
Oct 28 17:25:28 One kernel: bad: scheduling from the idle thread!
Oct 28 17:25:28 One kernel: Pid: 0, comm: swapper Tainted: P          2.6.27.4-47.rc3.fc10.x86_64 #1
Oct 28 17:25:28 One kernel:
Oct 28 17:25:28 One kernel: Call Trace:
Oct 28 17:25:28 One kernel: [<ffffffff81034491>] dequeue_task_idle+0x32/0x3f
Oct 28 17:25:28 One kernel: [<ffffffff81032bd2>] dequeue_task+0xbf/0xca
Oct 28 17:25:28 One kernel: [<ffffffff81032c29>] deactivate_task+0x22/0x2b
Oct 28 17:25:28 One kernel: [<ffffffff813555e4>] schedule+0x1f5/0x816
Oct 28 17:25:28 One kernel: [<ffffffff811c05b0>] ? acpi_state_timer_broadcast+0x41/0x43
Oct 28 17:25:28 One kernel: [<ffffffff811c0c35>] ? acpi_idle_enter_bm+0x2c7/0x2e7
Oct 28 17:25:28 One kernel: [<ffffffff8100f2cd>] cpu_idle+0x106/0x10b
Oct 28 17:25:28 One kernel: [<ffffffff81351f8f>] start_secondary+0x16e/0x173
Oct 28 17:25:28 One kernel:
Oct 28 17:25:28 One kernel: Kernel logging (proc) stopped.
Comment 2 Tom London 2008-11-02 00:39:27 UTC 
Got this again with 4-69.fc10.x86_64:

[root@tlondon ~]# ls -l /var/log/messages
-rw------- 1 root root 5394885080 2008-11-01 17:36 /var/log/messages
[root@tlondon ~]# 

Is there some additional information I can provide that would be helpful?

Nov  1 17:31:34 tlondon kernel: bad: scheduling from the idle thread!
Nov  1 17:31:34 tlondon kernel: Pid: 0, comm: swapper Not tainted 2.6.27.4-69.fc10.x86_64 #1
Nov  1 17:31:34 tlondon kernel:
Nov  1 17:31:34 tlondon kernel: Call Trace:
Nov  1 17:31:34 tlondon kernel: [<ffffffff81033770>] dequeue_task_idle+0x32/0x3f
Nov  1 17:31:34 tlondon kernel: [<ffffffff81031a62>] dequeue_task+0xbf/0xca
Nov  1 17:31:34 tlondon kernel: [<ffffffff81031ab9>] deactivate_task+0x22/0x2b
Nov  1 17:31:34 tlondon kernel: [<ffffffff81352dc0>] schedule+0x1f2/0x7c5
Nov  1 17:31:34 tlondon kernel: [<ffffffff810575aa>] ? enqueue_hrtimer+0xd3/0xe1
Nov  1 17:31:34 tlondon kernel: [<ffffffff8100f2cd>] cpu_idle+0x106/0x10b
Nov  1 17:31:34 tlondon kernel: [<ffffffff8134f7a6>] start_secondary+0x16e/0x173
Nov  1 17:31:34 tlondon kernel:
Nov  1 17:31:34 tlondon kernel: bad: scheduling from the idle thread!
Nov  1 17:31:34 tlondon kernel: Pid: 0, comm: swapper Not tainted 2.6.27.4-69.fc10.x86_64 #1
Nov  1 17:31:34 tlondon kernel:
Nov  1 17:31:34 tlondon kernel: Call Trace:
Nov  1 17:31:34 tlondon kernel: [<ffffffff81033770>] dequeue_task_idle+0x32/0x3f
Nov  1 17:31:34 tlondon kernel: [<ffffffff81031a62>] dequeue_task+0xbf/0xca
Nov  1 17:31:34 tlondon kernel: [<ffffffff81031ab9>] deactivate_task+0x22/0x2b
Nov  1 17:31:34 tlondon kernel: [<ffffffff81352dc0>] schedule+0x1f2/0x7c5
Nov  1 17:31:34 tlondon kernel: [<ffffffff810575aa>] ? enqueue_hrtimer+0xd3/0xe1
Nov  1 17:31:34 tlondon kernel: [<ffffffff8100f2cd>] cpu_idle+0x106/0x10b
Nov  1 17:31:34 tlondon kernel: [<ffffffff8134f7a6>] start_secondary+0x16e/0x173
Nov  1 17:31:34 tlondon kernel:
Comment 3 Tom London 2008-11-02 00:54:07 UTC 
OK, I managed to "split" /var/log/messages so I could extract some context.

Looks like before this starts happening the kernel throws a BUG or 2:

Nov  1 17:02:39 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> group handshake
Nov  1 17:02:39 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov  1 17:03:55 tlondon kernel: BUG: scheduling while atomic: swapper/0/0x00000100
Nov  1 17:03:55 tlondon kernel: Modules linked in: i915 drm ipt_MASQUERADE iptable_nat nf_nat rfcomm sco bridge stp bnep l2cap sunrpc ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 cpufreq_ondemand acpi_cpufreq freq_table fuse dm_multipath kvm_intel kvm uinput snd_hda_intel snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_page_alloc snd_hwdep snd iwlagn ppdev thinkpad_acpi soundcore video firewire_ohci sdhci_pci iwlcore sdhci output parport_pc firewire_core yenta_socket pcspkr hwmon btusb i2c_i801 mmc_core rsrc_nonstatic parport e1000e i2c_core rfkill iTCO_wdt iTCO_vendor_support bluetooth crc_itu_t battery ac sha256_generic cbc aes_x86_64 dm_crypt [last unloaded: microcode]
Nov  1 17:03:55 tlondon kernel: CPU 1:
Nov  1 17:03:55 tlondon kernel: Modules linked in: i915 drm ipt_MASQUERADE iptable_nat nf_nat rfcomm sco bridge stp bnep l2cap sunrpc ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 cpufreq_ondemand acpi_cpufreq freq_table fuse dm_multipath kvm_intel kvm uinput snd_hda_intel snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_page_alloc snd_hwdep snd iwlagn ppdev thinkpad_acpi soundcore video firewire_ohci sdhci_pci iwlcore sdhci output parport_pc firewire_core yenta_socket pcspkr hwmon btusb i2c_i801 mmc_core rsrc_nonstatic parport e1000e i2c_core rfkill iTCO_wdt iTCO_vendor_support bluetooth crc_itu_t battery ac sha256_generic cbc aes_x86_64 dm_crypt [last unloaded: microcode]
Nov  1 17:03:55 tlondon kernel: Pid: 0, comm: swapper Not tainted 2.6.27.4-69.fc10.x86_64 #1
Nov  1 17:03:55 tlondon kernel: RIP: 0010:[<ffffffff811be91b>]  [<ffffffff811be91b>] acpi_idle_enter_bm+0x296/0x2e6
Nov  1 17:03:55 tlondon kernel: RSP: 0018:ffff88007d3e3e98  EFLAGS: 00000246
Nov  1 17:03:55 tlondon kernel: RAX: ffffffff81700510 RBX: ffff88007d3e3ed8 RCX: 000000007d3e3e68
Nov  1 17:03:55 tlondon kernel: RDX: ffff88007f929000 RSI: 00000680c71fcf74 RDI: ffff88000102de80
Nov  1 17:03:55 tlondon kernel: RBP: ffff88007d3e3e28 R08: 0000000000000003 R09: 0000000000000015
Nov  1 17:03:55 tlondon kernel: R10: 0000000000000000 R11: 0000000000000818 R12: 00000000005215a4
Nov  1 17:03:55 tlondon kernel: R13: ffff88007d3e3e38 R14: ffffffff8105a16f R15: ffff88007d3e3e08
Nov  1 17:03:55 tlondon kernel: FS:  0000000000000000(0000) GS:ffff88007d004880(0000) knlGS:0000000000000000
Nov  1 17:03:55 tlondon kernel: CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
Nov  1 17:03:55 tlondon kernel: CR2: 00007f850415d000 CR3: 0000000000201000 CR4: 00000000000026e0
Nov  1 17:03:55 tlondon kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Nov  1 17:03:55 tlondon kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Nov  1 17:03:55 tlondon kernel:
Nov  1 17:03:55 tlondon kernel: Call Trace:
Nov  1 17:03:55 tlondon kernel: [<ffffffff811be913>] ? acpi_idle_enter_bm+0x28e/0x2e6
Nov  1 17:03:55 tlondon kernel: [<ffffffff81287d83>] ? cpuidle_idle_call+0x95/0xc9
Nov  1 17:03:55 tlondon kernel: [<ffffffff8100f279>] ? cpu_idle+0xb2/0x10b
Nov  1 17:03:55 tlondon kernel: [<ffffffff8134f7a6>] ? start_secondary+0x16e/0x173
Nov  1 17:03:55 tlondon kernel:
Nov  1 17:03:55 tlondon kernel: bad: scheduling from the idle thread!
Nov  1 17:03:55 tlondon kernel: Pid: 0, comm: swapper Not tainted 2.6.27.4-69.fc10.x86_64 #1
Nov  1 17:03:55 tlondon kernel:
Nov  1 17:03:55 tlondon kernel: Call Trace:
Nov  1 17:03:55 tlondon kernel: <IRQ>  [<ffffffff81033770>] dequeue_task_idle+0x32/0x3f
Nov  1 17:03:55 tlondon kernel: [<ffffffff81031a62>] dequeue_task+0xbf/0xca
Nov  1 17:03:55 tlondon kernel: [<ffffffff81031ab9>] deactivate_task+0x22/0x2b
Nov  1 17:03:55 tlondon kernel: [<ffffffff81352dc0>] schedule+0x1f2/0x7c5
Nov  1 17:03:55 tlondon kernel: [<ffffffff810551a2>] ? autoremove_wake_function+0x11/0x38
Nov  1 17:03:55 tlondon kernel: [<ffffffff81355049>] ? _spin_lock_irqsave+0x2a/0x33
Nov  1 17:03:55 tlondon kernel: [<ffffffff8104b613>] ? __mod_timer+0xbb/0xcd
Nov  1 17:03:55 tlondon kernel: [<ffffffff8135384b>] schedule_timeout+0x8d/0xb4
Nov  1 17:03:55 tlondon kernel: [<ffffffff8104afdc>] ? process_timeout+0x0/0xb
Nov  1 17:03:55 tlondon kernel: [<ffffffff8104b574>] ? __mod_timer+0x1c/0xcd
Nov  1 17:03:55 tlondon kernel: [<ffffffff8135388b>] schedule_timeout_uninterruptible+0x19/0x1b
Nov  1 17:03:55 tlondon kernel: [<ffffffff8104b639>] msleep+0x14/0x1e
Nov  1 17:03:55 tlondon kernel: [<ffffffffa00ea431>] iwl_scan_cancel_timeout+0x48/0x8f [iwlcore]
Nov  1 17:03:55 tlondon kernel: [<ffffffffa0135138>] iwl4965_mac_update_tkip_key+0x11f/0x239 [iwlagn]
Nov  1 17:03:55 tlondon kernel: [<ffffffff81096fbf>] ? put_compound_page+0x32/0x36
Nov  1 17:03:55 tlondon kernel: [<ffffffff8132d823>] ieee80211_tkip_decrypt_data+0x162/0x1d4
Nov  1 17:03:55 tlondon kernel: [<ffffffff813253ae>] ieee80211_crypto_tkip_decrypt+0xbe/0x10b
Nov  1 17:03:55 tlondon kernel: [<ffffffff8132f7b1>] ieee80211_invoke_rx_handlers+0x34c/0x1425
Nov  1 17:03:55 tlondon kernel: [<ffffffffa00dfed6>] ? iwl_pass_packet_to_mac80211+0x572/0x591 [iwlcore]
Nov  1 17:03:55 tlondon kernel: [<ffffffffa00e07b8>] ? iwl_rx_reply_rx+0x8c3/0x8d5 [iwlcore]
Nov  1 17:03:55 tlondon kernel: [<ffffffff810597de>] ? sched_clock_cpu+0x10f/0x120
Nov  1 17:03:55 tlondon kernel: [<ffffffff81354f14>] ? _spin_unlock_irqrestore+0x27/0x3e
Nov  1 17:03:55 tlondon kernel: [<ffffffff81330dc1>] __ieee80211_rx_handle_packet+0x537/0x557
Nov  1 17:03:55 tlondon kernel: [<ffffffff813314c7>] __ieee80211_rx+0x49d/0x4fa
Nov  1 17:03:55 tlondon kernel: [<ffffffff81321e70>] ieee80211_tasklet_handler+0x74/0xfe
Nov  1 17:03:55 tlondon kernel: [<ffffffff81046403>] tasklet_action+0x90/0xf9
Nov  1 17:03:55 tlondon kernel: [<ffffffff81046b1a>] __do_softirq+0x7e/0x10c
Nov  1 17:03:55 tlondon kernel: [<ffffffff81011bcc>] call_softirq+0x1c/0x28
Nov  1 17:03:55 tlondon kernel: [<ffffffff81012dd2>] do_softirq+0x4d/0xb0
Nov  1 17:03:55 tlondon kernel: [<ffffffff810466ef>] irq_exit+0x4e/0x9d
Nov  1 17:03:55 tlondon kernel: [<ffffffff810130ee>] do_IRQ+0x147/0x169
Nov  1 17:03:55 tlondon kernel: [<ffffffff81010933>] ret_from_intr+0x0/0x2e
Nov  1 17:03:55 tlondon kernel: <EOI>  [<ffffffff811be91b>] ? acpi_idle_enter_bm+0x296/0x2e6
Nov  1 17:03:55 tlondon kernel: [<ffffffff811be913>] ? acpi_idle_enter_bm+0x28e/0x2e6
Nov  1 17:03:55 tlondon kernel: [<ffffffff81287d83>] ? cpuidle_idle_call+0x95/0xc9
Nov  1 17:03:55 tlondon kernel: [<ffffffff8100f279>] ? cpu_idle+0xb2/0x10b
Nov  1 17:03:55 tlondon kernel: [<ffffffff8134f7a6>] ? start_secondary+0x16e/0x173
Nov  1 17:03:55 tlondon kernel:
Nov  1 17:03:55 tlondon kernel: BUG: scheduling while atomic: swapper/0/0x00000100
Nov  1 17:03:55 tlondon kernel: Modules linked in: i915 drm ipt_MASQUERADE iptable_nat nf_nat rfcomm sco bridge stp bnep l2cap sunrpc ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 cpufreq_ondemand acpi_cpufreq freq_table fuse dm_multipath kvm_intel kvm uinput snd_hda_intel snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_page_alloc snd_hwdep snd iwlagn ppdev thinkpad_acpi soundcore video firewire_ohci sdhci_pci iwlcore sdhci output parport_pc firewire_core yenta_socket pcspkr hwmon btusb i2c_i801 mmc_core rsrc_nonstatic parport e1000e i2c_core rfkill iTCO_wdt iTCO_vendor_support bluetooth crc_itu_t battery ac sha256_generic cbc aes_x86_64 dm_crypt [last unloaded: microcode]
Nov  1 17:03:55 tlondon kernel: CPU 1:
Nov  1 17:03:55 tlondon kernel: Modules linked in: i915 drm ipt_MASQUERADE iptable_nat nf_nat rfcomm sco bridge stp bnep l2cap sunrpc ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 cpufreq_ondemand acpi_cpufreq freq_table fuse dm_multipath kvm_intel kvm uinput snd_hda_intel snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_page_alloc snd_hwdep snd iwlagn ppdev thinkpad_acpi soundcore video firewire_ohci sdhci_pci iwlcore sdhci output parport_pc firewire_core yenta_socket pcspkr hwmon btusb i2c_i801 mmc_core rsrc_nonstatic parport e1000e i2c_core rfkill iTCO_wdt iTCO_vendor_support bluetooth crc_itu_t battery ac sha256_generic cbc aes_x86_64 dm_crypt [last unloaded: microcode]
Nov  1 17:03:55 tlondon kernel: Pid: 0, comm: swapper Not tainted 2.6.27.4-69.fc10.x86_64 #1
Nov  1 17:03:55 tlondon kernel: RIP: 0010:[<ffffffff811be91b>]  [<ffffffff811be91b>] acpi_idle_enter_bm+0x296/0x2e6
Nov  1 17:03:55 tlondon kernel: RSP: 0018:ffff88007d3e3e98  EFLAGS: 00000246
Nov  1 17:03:55 tlondon kernel: RAX: ffffffff81700510 RBX: ffff88007d3e3ed8 RCX: 000000007d3e3e68
Nov  1 17:03:55 tlondon kernel: RDX: ffff88007f929000 RSI: 00000680c71fcf74 RDI: ffff88000102de80
Nov  1 17:03:55 tlondon kernel: RBP: ffff88007d3e3e28 R08: 0000000000000003 R09: 0000000000000015
Nov  1 17:03:55 tlondon kernel: R10: 0000000000000000 R11: 0000000000000818 R12: 00000000005215a4
Nov  1 17:03:55 tlondon kernel: R13: ffff88007d3e3e38 R14: ffffffff8105a16f R15: ffff88007d3e3e08
Nov  1 17:03:55 tlondon kernel: FS:  0000000000000000(0000) GS:ffff88007d004880(0000) knlGS:0000000000000000
Nov  1 17:03:55 tlondon kernel: CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
Nov  1 17:03:55 tlondon kernel: CR2: 00007fd814006118 CR3: 00000000378fa000 CR4: 00000000000026e0
Nov  1 17:03:55 tlondon kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Nov  1 17:03:55 tlondon kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Nov  1 17:03:55 tlondon kernel:
Nov  1 17:03:55 tlondon kernel: Call Trace:
Nov  1 17:03:55 tlondon kernel: [<ffffffff811be913>] ? acpi_idle_enter_bm+0x28e/0x2e6
Nov  1 17:03:55 tlondon kernel: [<ffffffff81287d83>] ? cpuidle_idle_call+0x95/0xc9
Nov  1 17:03:55 tlondon kernel: [<ffffffff8100f279>] ? cpu_idle+0xb2/0x10b
Nov  1 17:03:55 tlondon kernel: [<ffffffff8134f7a6>] ? start_secondary+0x16e/0x173
Nov  1 17:03:55 tlondon kernel:
Nov  1 17:03:55 tlondon kernel: bad: scheduling from the idle thread!
Nov  1 17:03:55 tlondon kernel: Pid: 0, comm: swapper Not tainted 2.6.27.4-69.fc10.x86_64 #1
Nov  1 17:03:55 tlondon kernel:
Nov  1 17:03:55 tlondon kernel: Call Trace:
Nov  1 17:03:55 tlondon kernel: <IRQ>  [<ffffffff81033770>] dequeue_task_idle+0x32/0x3f
Nov  1 17:03:55 tlondon kernel: [<ffffffff81031a62>] dequeue_task+0xbf/0xca
Nov  1 17:03:55 tlondon kernel: [<ffffffff81031ab9>] deactivate_task+0x22/0x2b
Nov  1 17:03:55 tlondon kernel: [<ffffffff81352dc0>] schedule+0x1f2/0x7c5
Nov  1 17:03:55 tlondon kernel: [<ffffffff810551a2>] ? autoremove_wake_function+0x11/0x38
Nov  1 17:03:55 tlondon kernel: [<ffffffff81355049>] ? _spin_lock_irqsave+0x2a/0x33
Nov  1 17:03:55 tlondon kernel: [<ffffffff8104b613>] ? __mod_timer+0xbb/0xcd
Nov  1 17:03:55 tlondon kernel: [<ffffffff8135384b>] schedule_timeout+0x8d/0xb4
Nov  1 17:03:55 tlondon kernel: [<ffffffff8104afdc>] ? process_timeout+0x0/0xb
Nov  1 17:03:55 tlondon kernel: [<ffffffff8104b574>] ? __mod_timer+0x1c/0xcd
Nov  1 17:03:55 tlondon kernel: [<ffffffff8135388b>] schedule_timeout_uninterruptible+0x19/0x1b
Nov  1 17:03:55 tlondon kernel: [<ffffffff8104b639>] msleep+0x14/0x1e
Nov  1 17:03:55 tlondon kernel: [<ffffffffa00ea431>] iwl_scan_cancel_timeout+0x48/0x8f [iwlcore]
Nov  1 17:03:55 tlondon kernel: [<ffffffffa0135138>] iwl4965_mac_update_tkip_key+0x11f/0x239 [iwlagn]
Nov  1 17:03:55 tlondon kernel: [<ffffffff81096fbf>] ? put_compound_page+0x32/0x36
Nov  1 17:03:55 tlondon kernel: [<ffffffff8132d823>] ieee80211_tkip_decrypt_data+0x162/0x1d4
Nov  1 17:03:55 tlondon kernel: [<ffffffff813253ae>] ieee80211_crypto_tkip_decrypt+0xbe/0x10b
Nov  1 17:03:55 tlondon kernel: [<ffffffff8132f7b1>] ieee80211_invoke_rx_handlers+0x34c/0x1425
Nov  1 17:03:55 tlondon kernel: [<ffffffffa00dfed6>] ? iwl_pass_packet_to_mac80211+0x572/0x591 [iwlcore]
Nov  1 17:03:55 tlondon kernel: [<ffffffffa00e07b8>] ? iwl_rx_reply_rx+0x8c3/0x8d5 [iwlcore]
Nov  1 17:03:55 tlondon kernel: [<ffffffff810597de>] ? sched_clock_cpu+0x10f/0x120
Nov  1 17:03:55 tlondon kernel: [<ffffffff81354f14>] ? _spin_unlock_irqrestore+0x27/0x3e
Nov  1 17:03:55 tlondon kernel: [<ffffffff81330dc1>] __ieee80211_rx_handle_packet+0x537/0x557
Nov  1 17:03:55 tlondon kernel: [<ffffffff813314c7>] __ieee80211_rx+0x49d/0x4fa
Nov  1 17:03:55 tlondon kernel: [<ffffffff81321e70>] ieee80211_tasklet_handler+0x74/0xfe
Nov  1 17:03:55 tlondon kernel: [<ffffffff81046403>] tasklet_action+0x90/0xf9
Nov  1 17:03:55 tlondon kernel: [<ffffffff81046b1a>] __do_softirq+0x7e/0x10c
Nov  1 17:03:55 tlondon kernel: [<ffffffff81011bcc>] call_softirq+0x1c/0x28
Nov  1 17:03:55 tlondon kernel: [<ffffffff81012dd2>] do_softirq+0x4d/0xb0
Nov  1 17:03:55 tlondon kernel: [<ffffffff810466ef>] irq_exit+0x4e/0x9d
Nov  1 17:03:55 tlondon kernel: [<ffffffff810130ee>] do_IRQ+0x147/0x169
Nov  1 17:03:55 tlondon kernel: [<ffffffff81010933>] ret_from_intr+0x0/0x2e
Nov  1 17:03:55 tlondon kernel: <EOI>  [<ffffffff811be91b>] ? acpi_idle_enter_bm+0x296/0x2e6
Nov  1 17:03:55 tlondon kernel: [<ffffffff811be913>] ? acpi_idle_enter_bm+0x28e/0x2e6
Nov  1 17:03:55 tlondon kernel: [<ffffffff81287d83>] ? cpuidle_idle_call+0x95/0xc9
Nov  1 17:03:55 tlondon kernel: [<ffffffff8100f279>] ? cpu_idle+0xb2/0x10b
Nov  1 17:03:55 tlondon kernel: [<ffffffff8134f7a6>] ? start_secondary+0x16e/0x173
Nov  1 17:03:55 tlondon kernel:
Nov  1 17:03:55 tlondon kernel: BUG: sleeping function called from invalid context at kernel/mutex.c:88
Nov  1 17:03:55 tlondon kernel: in_atomic():1, irqs_disabled():0
Nov  1 17:03:55 tlondon kernel: Pid: 0, comm: swapper Not tainted 2.6.27.4-69.fc10.x86_64 #1
Nov  1 17:03:55 tlondon kernel:
Nov  1 17:03:55 tlondon kernel: Call Trace:
Nov  1 17:03:55 tlondon kernel: <IRQ>  [<ffffffff8103a0a1>] __might_sleep+0xe7/0xec
Nov  1 17:03:55 tlondon kernel: [<ffffffff81353ae9>] mutex_lock+0x1d/0x33
Nov  1 17:03:55 tlondon kernel: [<ffffffffa00ea461>] iwl_scan_cancel_timeout+0x78/0x8f [iwlcore]
Nov  1 17:03:55 tlondon kernel: [<ffffffffa0135138>] iwl4965_mac_update_tkip_key+0x11f/0x239 [iwlagn]
Nov  1 17:03:55 tlondon kernel: [<ffffffff81096fbf>] ? put_compound_page+0x32/0x36
Nov  1 17:03:55 tlondon kernel: [<ffffffff8132d823>] ieee80211_tkip_decrypt_data+0x162/0x1d4
Nov  1 17:03:55 tlondon kernel: [<ffffffff813253ae>] ieee80211_crypto_tkip_decrypt+0xbe/0x10b
Nov  1 17:03:55 tlondon kernel: [<ffffffff8132f7b1>] ieee80211_invoke_rx_handlers+0x34c/0x1425
Nov  1 17:03:55 tlondon kernel: [<ffffffffa00dfed6>] ? iwl_pass_packet_to_mac80211+0x572/0x591 [iwlcore]
Nov  1 17:03:55 tlondon kernel: [<ffffffffa00e07b8>] ? iwl_rx_reply_rx+0x8c3/0x8d5 [iwlcore]
Nov  1 17:03:55 tlondon kernel: [<ffffffff810597de>] ? sched_clock_cpu+0x10f/0x120
Nov  1 17:03:55 tlondon kernel: [<ffffffff81354f14>] ? _spin_unlock_irqrestore+0x27/0x3e
Nov  1 17:03:55 tlondon kernel: [<ffffffff81330dc1>] __ieee80211_rx_handle_packet+0x537/0x557
Nov  1 17:03:55 tlondon kernel: [<ffffffff813314c7>] __ieee80211_rx+0x49d/0x4fa
Nov  1 17:03:55 tlondon kernel: [<ffffffff81321e70>] ieee80211_tasklet_handler+0x74/0xfe
Nov  1 17:03:55 tlondon kernel: [<ffffffff81046403>] tasklet_action+0x90/0xf9
Nov  1 17:03:55 tlondon kernel: [<ffffffff81046b1a>] __do_softirq+0x7e/0x10c
Nov  1 17:03:55 tlondon kernel: [<ffffffff81011bcc>] call_softirq+0x1c/0x28
Nov  1 17:03:55 tlondon kernel: [<ffffffff81012dd2>] do_softirq+0x4d/0xb0
Nov  1 17:03:55 tlondon kernel: [<ffffffff810466ef>] irq_exit+0x4e/0x9d
Nov  1 17:03:55 tlondon kernel: [<ffffffff810130ee>] do_IRQ+0x147/0x169
Nov  1 17:03:55 tlondon kernel: [<ffffffff81010933>] ret_from_intr+0x0/0x2e
Nov  1 17:03:55 tlondon kernel: <EOI>  [<ffffffff811be91b>] ? acpi_idle_enter_bm+0x296/0x2e6
Nov  1 17:03:55 tlondon kernel: [<ffffffff811be913>] ? acpi_idle_enter_bm+0x28e/0x2e6
Nov  1 17:03:55 tlondon kernel: [<ffffffff81287d83>] ? cpuidle_idle_call+0x95/0xc9
Nov  1 17:03:55 tlondon kernel: [<ffffffff8100f279>] ? cpu_idle+0xb2/0x10b
Nov  1 17:03:55 tlondon kernel: [<ffffffff8134f7a6>] ? start_secondary+0x16e/0x173
Nov  1 17:03:55 tlondon kernel:
Nov  1 17:03:55 tlondon kernel: BUG: scheduling while atomic: swapper/0/0x10000100
Nov  1 17:03:55 tlondon kernel: Modules linked in: i915 drm ipt_MASQUERADE iptable_nat nf_nat rfcomm sco bridge stp bnep l2cap sunrpc ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 cpufreq_ondemand acpi_cpufreq freq_table fuse dm_multipath kvm_intel kvm uinput snd_hda_intel snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_page_alloc snd_hwdep snd iwlagn ppdev thinkpad_acpi soundcore video firewire_ohci sdhci_pci iwlcore sdhci output parport_pc firewire_core yenta_socket pcspkr hwmon btusb i2c_i801 mmc_core rsrc_nonstatic parport e1000e i2c_core rfkill iTCO_wdt iTCO_vendor_support bluetooth crc_itu_t battery ac sha256_generic cbc aes_x86_64 dm_crypt [last unloaded: microcode]
Nov  1 17:03:55 tlondon kernel: CPU 1:
Nov  1 17:03:55 tlondon kernel: Modules linked in: i915 drm ipt_MASQUERADE iptable_nat nf_nat rfcomm sco bridge stp bnep l2cap sunrpc ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 cpufreq_ondemand acpi_cpufreq freq_table fuse dm_multipath kvm_intel kvm uinput snd_hda_intel snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd_page_alloc snd_hwdep snd iwlagn ppdev thinkpad_acpi soundcore video firewire_ohci sdhci_pci iwlcore sdhci output parport_pc firewire_core yenta_socket pcspkr hwmon btusb i2c_i801 mmc_core rsrc_nonstatic parport e1000e i2c_core rfkill iTCO_wdt iTCO_vendor_support bluetooth crc_itu_t battery ac sha256_generic cbc aes_x86_64 dm_crypt [last unloaded: microcode]
Nov  1 17:03:55 tlondon kernel: Pid: 0, comm: swapper Not tainted 2.6.27.4-69.fc10.x86_64 #1
Nov  1 17:03:55 tlondon kernel: RIP: 0010:[<ffffffff811be91b>]  [<ffffffff811be91b>] acpi_idle_enter_bm+0x296/0x2e6
Nov  1 17:03:55 tlondon kernel: RSP: 0018:ffff88007d3e3e98  EFLAGS: 00000246
Nov  1 17:03:55 tlondon kernel: RAX: ffffffff81700510 RBX: ffff88007d3e3ed8 RCX: 000000007d3e3e68
Nov  1 17:03:55 tlondon kernel: RDX: ffff88007f929000 RSI: 00000680c71fcf74 RDI: ffff88000102de80
Nov  1 17:03:55 tlondon kernel: RBP: ffff88007d3e3e28 R08: 0000000000000003 R09: 0000000000000015
Comment 4 Billy Croan 2008-11-02 01:38:52 UTC 
Could this be related to WPA Enterprise?  I think this problem has only happened at work.  There, I use WPA Enterprise with a CA cert, username, and passphrase which involves many special characters.  I also use a docking station there.  Here's an lspci of my wlan adapter.  The next time I see this problem happen, I will try to catch it early enough, and get some context on what happens before it fills up with the repeating stanza.

My employer wouldn't mind me taking a few minutes to locate a kernel bug.  Let me know how I can help.

0c:00.0 Network controller [0280]: Intel Corporation PRO/Wireless 4965 AG or AGN Network Connection [8086:4229] (rev 61)
	Subsystem: Intel Corporation Device [8086:1120]
	Flags: bus master, fast devsel, latency 0, IRQ 10
	Memory at 00000000f1ffe000 (64-bit, non-prefetchable)
	Capabilities: [c8] Power Management version 3
	Capabilities: [d0] Message Signalled Interrupts: Mask- 64bit+ Count=1/1 Enable-
	Capabilities: [e0] Express Endpoint, MSI 00
	Capabilities: [100] Advanced Error Reporting
		UESta:	DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSVoil-
		UEMsk:	DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSVoil-
		UESvrt:	DLP+ SDES- TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSVoil-
		CESta:	RxErr+ BadTLP+ BadDLLP- Rollover- Timeout- NonFatalErr-
		CESta:	RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr+
		AERCap:	First Error Pointer: 00, GenCap- CGenEn- ChkCap- ChkEn-
	Capabilities: [140] Device Serial Number ed-03-7c-ff-ff-3b-1f-00
	Kernel driver in use: iwlagn
	Kernel modules: iwlagn
Comment 5 Chuck Ebbert 2008-11-02 04:30:50 UTC 
Does everyone who is reporting this have an Intel wireless adapter in use? If so, what kind is it and what kind of encryption is being used?
Comment 6 Billy Croan 2008-11-02 04:51:44 UTC 
I meant to say WPA2 Enterprise.  This appears to be a distro-agnostic problem.  I found a long bug in Canonical's Launchpad.  https://bugs.launchpad.net/ubuntu/+source/linux/+bug/286285  It seems related enough, and has enough momentum that I've posted my details there as well.

I've been looking in bugzilla.kernel.org but have not found anything yet relating to this issue.

Intel 4965AGN rev 61 is the adapter I use.  I use it with a 802.11G network when this happens.
Comment 7 Tom London 2008-11-02 14:59:36 UTC 
Yeah, Thinkpad X61 w/Intel 4965:

03:00.0 Network controller: Intel Corporation PRO/Wireless 4965 AG or AGN Network Connection (rev 61)

My network at home (the one I reported yesterday) uses WPA2 Personal, TKIP+AES.

Not 100% sure, but I think the first report was with WPA2 Enterprise....
Comment 8 Tom London 2008-11-02 16:42:56 UTC 
Not sure it's relevant, but I believe both of my "stanza syslog loops" occurred when I also had the wired NIC active.  So the wireless was active/associated, but not actually carrying traffic.  e.g.:

[root@tlondon ~]# route
Kernel IP routing table
Destination     Gateway         Genmask         Flags Metric Ref    Use Iface
192.168.1.0     *               255.255.255.0   U     1      0        0 eth0
192.168.1.0     *               255.255.255.0   U     2      0        0 wlan0
192.168.122.0   *               255.255.255.0   U     0      0        0 virbr0
default         192.168.1.1     0.0.0.0         UG    0      0        0 eth0
[root@tlondon ~]#
Comment 9 Tomasz Torcz 2008-11-06 17:15:18 UTC 
Thinkpad T400 with Intel AGN5300; 
IE: IEEE 802.11i/WPA2 Version 1
Group Cipher : TKIP
Pairwise Ciphers (1) : TKIP
Authentication Suites (1) : PSK
Comment 10 Luke Macken 2008-11-08 09:56:09 UTC 
For the past two nights in a row I've come home to a 20G /var/log/message, with this oops.  Running 2.6.27.4-79.fc10.x86_64 and an intel 4965 wireless card.

bad: scheduling from the idle thread!
Pid: 0, comm: swapper Not tainted 2.6.27.4-68.fc10.x86_64 #1

Call Trace:
 [<ffffffff81033770>] dequeue_task_idle+0x32/0x3f
 [<ffffffff81031a62>] dequeue_task+0xbf/0xca
 [<ffffffff81031ab9>] deactivate_task+0x22/0x2b
 [<ffffffff81352dc0>] schedule+0x1f2/0x7c5
 [<ffffffff81059906>] ? sched_clock_idle_wakeup_event+0xe/0x10
 [<ffffffff8105e68b>] ? tick_nohz_stop_idle+0x59/0x5d
 [<ffffffff8100f2cd>] cpu_idle+0x106/0x10b
 [<ffffffff8134201d>] rest_init+0x61/0x63
Comment 11 Chuck Ebbert 2008-11-10 23:25:48 UTC 
Should be fixed in 2.6.27.5-96
Comment 12 Will Woods 2008-11-12 16:26:05 UTC 
Tom, Luke, anyone else - can you confirm that this is fixed?
Comment 13 Tom London 2008-11-12 16:48:51 UTC 
A runable kernel with this fix just hit koji (kernel-2.6.27.5-101.fc10.x86_64), and I'm running it now.

Sorry, but I couldn't find 5-96 to download/install.

I'll run all day and report back.....
Comment 14 Tom London 2008-11-13 03:09:45 UTC 
I ran all day and did not have a recurrence.

But, I would only see this ever 3-5 days.....
Comment 15 Luke Macken 2008-11-13 04:20:58 UTC 
I've been running kernel-2.6.27.5-101.fc10.x86_64 all day, and have yet to hit this issue again.
Comment 16 Jeff Moyer 2009-03-17 21:29:37 UTC 
I've run into this on 2.6.29-0.237.rc7.git4.fc11.x86_64.  I also have an intel wireless chipset (3945) with wep encryption.  Let me know what other information I can provide.

As a side note, it would be really nice if there was a reference to the commit or patch that was supposed to address the issue when these bugs are marked resolved.  I know it's extra work, but it would make it easier for me to chip in on things like this.
Comment 17 Chuck Ebbert 2009-03-26 03:55:20 UTC 
The fix for this problem was:
http://git.kernel.org/?p=linux%2Fkernel%2Fgit%2Ftorvalds%2Flinux-2.6.git;a=commitdiff_plain;h=964d2777438bf7687324243d38ade538d9bbfe3c
Comment 18 Jeff Moyer 2009-03-26 13:48:18 UTC 
Thanks, chuck.  I think this was the result of a different problem that I was debugging, so I'm going to close it again.