Re: BUG: scheduling while atomic: ifconfig/0x00000002/4170
From: Satyam Sharma <hidden>
Date: 2007-09-06 04:49:39
Also in:
linux-wireless, lkml
Hi,
On 02/09/07, Florian Lohoff [off-list ref] wrote:quoted
Hi, with current git i got this when "ifconfig eth1" down. eth1 had a mac address which looked really like an eth1394 ethernet although the module was not loaded. Something is really broken in 2.6.23-currentgit. I always get the
-currentgit would be -rc5 right?
quoted
sysfs rename issues which are discussed to be an udev issue. Then i see a eth1394 mac address on an interface which typically shouldn exist (udev should rename the wireless to eth1) and when issueing an ifconfig eth1 down i get a BUG: scheduling while atomic: ifconfig/0x00000002/4170
Is this reproducible? Also, please send your .config. BTW the calltrace below shows that eth1 was the wireless interface when you tried to "down" it.
quoted
On the next boot i see the eth1394 mac address on the wireless interface wmaster0_rename whereas eth1 is active (the wireless) and has the correct ip address.
I don't think the "scheduling while atomic" bug you saw is related to the other problem you're seeing ... these are probably a bunch of all different issues, but I'm not sure if eth1394 is involved at all.
quoted
I dont get it - this all looks really messed up. udev is debian sid 114-2.
True, messed up it indeed is.
quoted
eth0 Link encap:Ethernet HWaddr 00:17:42:13:45:8C UP BROADCAST MULTICAST MTU:1500 Metric:1 RX packets:0 errors:0 dropped:0 overruns:0 frame:0 TX packets:0 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:0 (0.0 b) TX bytes:0 (0.0 b) Interrupt:19 eth1 Link encap:Ethernet HWaddr 00:18:DE:63:F0:B3 inet addr:195.71.97.208 Bcast:195.71.97.223 Mask:255.255.255.224 inet6 addr: fe80::218:deff:fe63:f0b3/64 Scope:Link UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:2079 errors:0 dropped:0 overruns:0 frame:0 TX packets:2220 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:508959 (497.0 KiB) TX bytes:261123 (255.0 KiB) wmaster0_ Link encap:UNSPEC HWaddr 00-18-DE-63-F0-B3-30-3A-00-00-00-00-00-00-00-00 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:0 errors:0 dropped:0 overruns:0 frame:0 TX packets:0 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:0 (0.0 b) TX bytes:0 (0.0 b) [ 14.300736] VFS: Mounted root (ext3 filesystem) readonly. [ 14.300902] Freeing unused kernel memory: 216k freed [ 17.618804] irda_init() [ 17.618817] NET: Registered protocol family 23 [ 17.636399] ACPI: PCI Interrupt 0000:02:00.0[A] -> GSI 16 (level, low) -> IRQ 19 [ 17.636588] PCI: Setting latency timer of device 0000:02:00.0 to 64 [ 17.636619] sky2 0000:02:00.0: v1.17 addr 0xf0000000 irq 19 Yukon-EC Ultra (0xb4) rev 2 [ 17.648081] parport_pc 00:0c: reported by Plug and Play ACPI [ 17.648206] parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE,EPP] [ 17.653652] sky2 eth0: addr 00:17:42:13:45:8c [ 17.680848] input: Video Bus as /class/input/input6 [ 17.680961] ACPI: Video Device [GFX0] (multi-head: yes rom: no post: no) [ 17.757019] usbcore: registered new interface driver usbfs [ 17.757139] usbcore: registered new interface driver hub [ 17.757264] usbcore: registered new device driver usb [ 17.824819] Yenta: CardBus bridge found at 0000:08:03.0 [10cf:131e] [ 17.824941] Yenta O2: res at 0x94/0xD4: 00/ea [ 17.825034] Yenta O2: enabling read prefetch/write burst [ 17.828363] hda: ATAPI 24X DVD-ROM DVD-R CD-R/RW drive, 2048kB Cache, UDMA(33) [ 17.828838] Uniform CD-ROM driver Revision: 3.20 [ 17.891481] USB Universal Host Controller Interface driver v3.0 [ 17.891650] ACPI: PCI Interrupt 0000:00:1d.0[A] -> GSI 23 (level, low) -> IRQ 22 [ 17.891840] PCI: Setting latency timer of device 0000:00:1d.0 to 64 [ 17.891844] uhci_hcd 0000:00:1d.0: UHCI Host Controller [ 17.892155] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 1 [ 17.892327] uhci_hcd 0000:00:1d.0: irq 22, io base 0x00001820 [ 17.892571] usb usb1: configuration #1 chosen from 1 choice [ 17.892689] hub 1-0:1.0: USB hub found [ 17.892784] hub 1-0:1.0: 2 ports detected [ 17.924265] found SMC SuperIO Chip (devid=0x7a rev=00 base=0x002e): LPC47N227 [ 17.924390] smsc_superio_flat(): fir: 0x6e8, sir: 0x2e8, dma: 03, irq: 3, mode: 0x0e [ 17.924526] smsc_ircc_present: can't get sir_base of 0x2e8 [ 17.954918] Yenta: ISA IRQ mask 0x0c38, PCI irq 19 [ 17.955009] Socket status: 30000006 [ 17.955094] Yenta: Raising subordinate bus# of parent bus (#08) from #09 to #0c [ 17.955225] pcmcia: parent PCI bridge I/O window: 0x3000 - 0x3fff [ 17.955315] cs: IO port probe 0x3000-0x3fff: clean. [ 17.955773] pcmcia: parent PCI bridge Memory window: 0xf0200000 - 0xf02fffff [ 17.955864] pcmcia: parent PCI bridge Memory window: 0x30000000 - 0x37ffffff [ 17.956497] Yenta: CardBus bridge found at 0000:08:03.1 [10cf:131e] [ 17.981605] iwl3945: Intel(R) PRO/Wireless 3945ABG/BG Network Connection driver for Linux, 0.1.14 [ 17.981752] iwl3945: Copyright(c) 2003-2007 Intel Corporation
Cc'ing ipw3945 ...
quoted
[ 17.983847] sdhci: Secure Digital Host Controller Interface driver [ 17.983940] sdhci: Copyright(c) Pierre Ossman [ 17.998087] ACPI: PCI Interrupt 0000:00:1d.1[B] -> GSI 20 (level, low) -> IRQ 18 [ 17.998299] PCI: Setting latency timer of device 0000:00:1d.1 to 64 [ 17.998303] uhci_hcd 0000:00:1d.1: UHCI Host Controller [ 17.998428] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 2 [ 17.998601] uhci_hcd 0000:00:1d.1: irq 18, io base 0x00001840 [ 17.998811] usb usb2: configuration #1 chosen from 1 choice [ 17.998933] hub 2-0:1.0: USB hub found [ 17.999023] hub 2-0:1.0: 2 ports detected [ 18.082862] Yenta: ISA IRQ mask 0x0438, PCI irq 19 [ 18.082956] Socket status: 30000410 [ 18.083041] Yenta: Raising subordinate bus# of parent bus (#08) from #0c to #10 [ 18.083169] pcmcia: parent PCI bridge I/O window: 0x3000 - 0x3fff [ 18.083255] cs: IO port probe 0x3000-0x3fff: clean. [ 18.083710] pcmcia: parent PCI bridge Memory window: 0xf0200000 - 0xf02fffff [ 18.083798] pcmcia: parent PCI bridge Memory window: 0x30000000 - 0x37ffffff [ 18.105897] ACPI: PCI Interrupt 0000:00:1d.2[C] -> GSI 18 (level, low) -> IRQ 20 [ 18.106097] PCI: Setting latency timer of device 0000:00:1d.2 to 64 [ 18.106101] uhci_hcd 0000:00:1d.2: UHCI Host Controller [ 18.106218] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 3 [ 18.106385] uhci_hcd 0000:00:1d.2: irq 20, io base 0x00001860 [ 18.106594] usb usb3: configuration #1 chosen from 1 choice [ 18.106709] hub 3-0:1.0: USB hub found [ 18.106799] hub 3-0:1.0: 2 ports detected [ 18.213730] ACPI: PCI Interrupt 0000:00:1d.3[D] -> GSI 16 (level, low) -> IRQ 19 [ 18.213932] PCI: Setting latency timer of device 0000:00:1d.3 to 64 [ 18.213938] uhci_hcd 0000:00:1d.3: UHCI Host Controller [ 18.214052] uhci_hcd 0000:00:1d.3: new USB bus registered, assigned bus number 4 [ 18.214210] uhci_hcd 0000:00:1d.3: irq 19, io base 0x00001880 [ 18.214414] usb usb4: configuration #1 chosen from 1 choice [ 18.214529] hub 4-0:1.0: USB hub found [ 18.214620] hub 4-0:1.0: 2 ports detected [ 18.318020] ACPI: PCI Interrupt 0000:00:1d.7[A] -> GSI 23 (level, low) -> IRQ 22 [ 18.324538] PCI: Setting latency timer of device 0000:00:1d.7 to 64 [ 18.324544] ehci_hcd 0000:00:1d.7: EHCI Host Controller [ 18.324687] ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 5 [ 18.324857] ehci_hcd 0000:00:1d.7: debug port 1 [ 18.324951] PCI: cache line size of 32 is not supported by device 0000:00:1d.7 [ 18.324959] ehci_hcd 0000:00:1d.7: irq 22, io mem 0xf0644000 [ 18.328914] ehci_hcd 0000:00:1d.7: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004 [ 18.329163] usb usb5: configuration #1 chosen from 1 choice [ 18.329282] hub 5-0:1.0: USB hub found [ 18.329374] hub 5-0:1.0: 8 ports detected [ 18.429643] ACPI: PCI Interrupt 0000:08:03.4[A] -> GSI 16 (level, low) -> IRQ 19 [ 18.480534] ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[19] MMIO=[f0201000-f02017ff] Max Packet=[2048] IR/IT contexts=[8/8] [ 18.483902] ACPI: PCI Interrupt 0000:05:00.0[A] -> GSI 18 (level, low) -> IRQ 20 [ 18.484135] PCI: Setting latency timer of device 0000:05:00.0 to 64 [ 18.484153] iwl3945: Detected Intel PRO/Wireless 3945ABG Network Connection
quoted
[ 18.595000] sdhci: SDHCI controller found at 0000:08:03.2 [1217:7120] (rev 1) [ 18.595114] ACPI: PCI Interrupt 0000:08:03.2[A] -> GSI 16 (level, low) -> IRQ 19 [ 18.595299] sdhci:slot0: Unknown controller version (16). You may experience problems. [ 18.595581] mmc0: SDHCI at 0xf0202800 irq 19 PIO [ 18.614800] ACPI: PCI Interrupt 0000:00:1b.0[A] -> GSI 17 (level, low) -> IRQ 23 [ 18.614990] PCI: Setting latency timer of device 0000:00:1b.0 to 64 [ 18.700659] iwl3945: Tunable channels: 13 802.11bg, 23 802.11a channels [ 18.701906] wmaster0: Selected rate control algorithm 'iwl-3945-rs'
iwl3945 is wmaster0
quoted
[ 18.721016] pccard: PCMCIA card inserted into slot 1 [ 18.721131] cs: memory probe 0xf0200000-0xf02fffff: excluding 0xf0200000-0xf020ffff [ 18.739151] pcmcia: registering new device pcmcia1.0
quoted
[ 18.740929] net eth1: device_rename: sysfs_create_symlink failed (-17)
quoted
[ 18.741075] net wlan0_rename: device_rename: sysfs_create_symlink failed (-17)
These look like interesting bits here ... sysfs_create_symlink() failed with the infamous -EEXIST. Those were actually two different calls to dev_change_name()->device_rename()->sysfs_create_symlink() it appears. If this is reproducible, please rebuild with a kernel with debugging config options enabled and reproduce.
quoted
[ 18.741625] udev: renamed network interface wmaster0 to eth1
But did this wmaster0 -> eth1 actually succeed, is the question.
quoted
[ 18.779425] cs: IO port probe 0x100-0x3af:<3>si3054: cannot initialize. EXT MID = 0000 [ 18.783468] clean. [ 18.783592] cs: IO port probe 0x3e0-0x4ff: excluding 0x4d0-0x4d7 [ 18.784668] cs: IO port probe 0x820-0x8ff: clean. [ 18.785521] cs: IO port probe 0xc00-0xcf7: clean. [ 18.786456] cs: IO port probe 0xa00-0xaff: clean. [ 18.837550] cs: IO port probe 0x100-0x3af: clean. [ 18.839641] cs: IO port probe 0x3e0-0x4ff: excluding 0x4d0-0x4d7 [ 18.840664] cs: IO port probe 0x820-0x8ff: clean. [ 18.841501] cs: IO port probe 0xc00-0xcf7: clean. [ 18.842426] cs: IO port probe 0xa00-0xaff: clean. [ 18.964571] usb 4-2: new full speed USB device using uhci_hcd and address 2 [ 19.141976] usb 4-2: configuration #1 chosen from 1 choice [ 19.214394] Bluetooth: Core ver 2.11 [ 19.214546] NET: Registered protocol family 31 [ 19.214640] Bluetooth: HCI device and connection manager initialized [ 19.214737] Bluetooth: HCI socket layer initialized [ 19.257180] Bluetooth: HCI USB driver ver 2.9 [ 19.257349] usbcore: registered new interface driver hci_usb [ 19.751313] ieee1394: Host added: ID:BUS[0-00:1023] GUID[00000e10036532e4] [ 50.113619] Adding 979924k swap on /dev/sda5. Priority:-1 extents:1 across:979924k [ 50.163229] EXT3 FS on sda6, internal journal [ 64.870417] NET: Registered protocol family 10 [ 64.870613] lo: Disabled Privacy Extensions [ 71.028607] Bluetooth: L2CAP ver 2.8 [ 71.028615] Bluetooth: L2CAP socket layer initialized [ 71.168926] Bluetooth: RFCOMM socket layer initialized [ 71.169019] Bluetooth: RFCOMM TTY layer initialized [ 71.169054] Bluetooth: RFCOMM ver 1.8 [ 71.539346] ADDRCONF(NETDEV_UP): wlan0_rename: link is not ready [ 71.737809] sky2 eth0: enabling interface [ 71.740794] sky2 eth0: ram buffer 0K [ 71.741733] ADDRCONF(NETDEV_UP): eth0: link is not ready
quoted
[ 142.968449] wlan0_rename: Initial auth_alg=0 [ 142.968461] wlan0_rename: authenticate with AP 00:0c:41:de:12:e1 [ 142.976883] wlan0_rename: RX authentication from 00:0c:41:de:12:e1 (alg=0 transaction=2 status=0) [ 142.976891] wlan0_rename: authenticated [ 142.976895] wlan0_rename: associate with AP 00:0c:41:de:12:e1 [ 142.979389] wlan0_rename: authentication frame received from 00:0c:41:de:12:e1, but not in authenticate state - ignored [ 142.980404] wlan0_rename: RX AssocResp from 00:0c:41:de:12:e1 (capab=0x401 status=0 aid=1) [ 142.980412] wlan0_rename: associated [ 142.982914] ADDRCONF(NETDEV_CHANGE): wlan0_rename: link becomes ready [ 148.291754] ICMPv6 NA: someone advertises our address on wlan0_rename! [ 151.386585] wlan0_rename: duplicate address detected!
quoted
[ 382.517007] BUG: scheduling while atomic: ifconfig/0x00000002/4170 [ 382.517029] [<c032bf5c>] __sched_text_start+0x84/0x71c [ 382.517047] [<c032c5da>] __sched_text_start+0x702/0x71c [ 382.517065] [<c0174a6c>] link_path_walk+0xa9/0xb3 [ 382.517079] [<c032c6ad>] wait_for_completion+0x65/0x9b [ 382.517090] [<c011f0a2>] default_wake_function+0x0/0xc [ 382.517103] [<c01334cf>] synchronize_rcu+0x2a/0x2f [ 382.517115] [<c0133091>] wakeme_after_rcu+0x0/0x8 [ 382.517127] [<c02d5f4f>] dev_deactivate+0x89/0x9c [ 382.517138] [<c02c8abc>] dev_close+0x24/0x67 [ 382.517150] [<e01f402b>] ieee80211_master_stop+0x4a/0x6d [mac80211] [ 382.517176] [<c02c8ae3>] dev_close+0x4b/0x67 [ 382.517183] [<c02c7f47>] dev_change_flags+0x9d/0x14e [ 382.517193] [<c03058c8>] devinet_ioctl+0x224/0x532 [ 382.517201] [<c02c9589>] dev_ifsioc+0x113/0x396 [ 382.517208] [<c02c8d59>] dev_load+0x24/0x4b [ 382.517214] [<c02be61d>] sock_ioctl+0x0/0x1be [ 382.517233] [<c02be7bc>] sock_ioctl+0x19f/0x1be [ 382.517239] [<c011a993>] do_page_fault+0x269/0x58e [ 382.517246] [<c02be61d>] sock_ioctl+0x0/0x1be [ 382.517254] [<c0176787>] do_ioctl+0x1f/0x62 [ 382.517263] [<c0176a01>] vfs_ioctl+0x237/0x249 [ 382.517270] [<c016b7d8>] do_sys_open+0xbb/0xc5 [ 382.517280] [<c0176a46>] sys_ioctl+0x33/0x4d [ 382.517288] [<c0103e52>] sysenter_past_esp+0x5f/0x85 [ 382.517303] =======================
quoted
[ 382.528958] BUG: scheduling while atomic: ifconfig/0x00000002/4170 [ 382.528972] [<c032bf5c>] __sched_text_start+0x84/0x71c [ 382.528996] [<c032c6ad>] wait_for_completion+0x65/0x9b [ 382.529005] [<c011f0a2>] default_wake_function+0x0/0xc [ 382.529014] [<c01334cf>] synchronize_rcu+0x2a/0x2f [ 382.529021] [<c0133091>] wakeme_after_rcu+0x0/0x8 [ 382.529031] [<c02d5f4f>] dev_deactivate+0x89/0x9c
Probably tangential, but Herbert, is the call to synchronize_rcu() in dev_deactivate() really correct? I saw that you put it in commit d4828d85d188dc70 about a year back and it's supposed to ensure that all outstanding transmissions from dev_queue_xmit() are over before proceeding. However, I think it may not serve that purpose -- as the comment before synchronize_rcu() and its use of call_rcu() [and not of call_rcu_bh()] indicate, synchronize_rcu() is used to synchronize with all outstanding rcu_read_lock() uses. OTOH, dev_queue_xmit() uses rcu_read_lock_*bh*() which isn't really the same -- bh / non-bh RCU callbacks have separate lists in the RCU implementation, so I don't really see anything preventing old transmissions to remain outstanding even after the synchronize_rcu() call in dev_deactivate (?) Whether that has anything to do with this particular bug or not, I have no idea ...
quoted
[ 382.529041] [<c02c8abc>] dev_close+0x24/0x67 [ 382.529052] [<e01f402b>] ieee80211_master_stop+0x4a/0x6d [mac80211] [ 382.529077] [<c02c8ae3>] dev_close+0x4b/0x67 [ 382.529088] [<c02c7f47>] dev_change_flags+0x9d/0x14e [ 382.529101] [<c03058c8>] devinet_ioctl+0x224/0x532 [ 382.529111] [<c02c9589>] dev_ifsioc+0x113/0x396 [ 382.529122] [<c02c8d59>] dev_load+0x24/0x4b [ 382.529132] [<c02be61d>] sock_ioctl+0x0/0x1be [ 382.529153] [<c02be7bc>] sock_ioctl+0x19f/0x1be [ 382.529164] [<c011a993>] do_page_fault+0x269/0x58e [ 382.529174] [<c02be61d>] sock_ioctl+0x0/0x1be [ 382.529187] [<c0176787>] do_ioctl+0x1f/0x62 [ 382.529201] [<c0176a01>] vfs_ioctl+0x237/0x249 [ 382.529211] [<c016b7d8>] do_sys_open+0xbb/0xc5 [ 382.529224] [<c0176a46>] sys_ioctl+0x33/0x4d [ 382.529235] [<c0103e52>] sysenter_past_esp+0x5f/0x85 [ 382.529253] ======================= [ 382.530962] Freeing alive inet6 address cd98f600
Unrelated, but I also wish the "BUG: scheduling while atomic" was the more instructive show_regs() trace and not a dump_stack() ... I'll make such a patch today itself.