Hi,
quoted text > On 02/09/07, Florian Lohoff <flo@rfc822.org> wrote:
> >
> > 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 text > > 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 text > > 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 text > > I dont get it - this all looks really messed up. udev is
> > debian sid 114-2.
True, messed up it indeed is.
quoted text > > 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 text > > [ 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 text > > [ 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 text > > [ 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 text > > [ 18.740929] net eth1: device_rename: sysfs_create_symlink failed (-17)
quoted text > > [ 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 text > > [ 18.741625] udev: renamed network interface wmaster0 to eth1
But did this wmaster0 -> eth1 actually succeed, is the question.
quoted text > > [ 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 text > > [ 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 text > > [ 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 text > > [ 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 text > > [ 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.
-
unsubscribe notice To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to
majordomo@vger.kernel.org
More majordomo info at
http://vger.kernel.org/majordomo-info.html
Please read the FAQ at
http://www.tux.org/lkml/ Messages in current thread:
Re: BUG: scheduling while atomic: ifconfig/0x00000002/4170 , Satyam Sharma , (Wed Sep 5, 10:02 pm)
