linux-2.6.17-mm6: strange kobject message

linux-2.6.17-mm6: strange kobject message

[Paul Drynoff]

Here is dmesg which I got during boot,
the first part not interesting I already reported about it,
and I don't remember one of two things: Arjan van de Ven's patch was
lost or not good enough. The second part is related to kobject,
I'm not sure is it normal when kobject tell about -EEXIST and print stack?
Note that this is happened only once per 100 normal booting, I mean the second part.

=================================
[ INFO: inconsistent lock state ]
---------------------------------
inconsistent {hardirq-on-W} -> {in-hardirq-W} usage.
dhclient/1952 [HC1[1]:SC0[1]:HE0:SE0] takes:
 (&ei_local->page_lock){+...}, at: [<c039d78d>] ei_interrupt+0x39/0x32c
{hardirq-on-W} state was registered at:
  [<c0133f5b>] lock_acquire+0x57/0x74
  [<c05b15c2>] _spin_lock+0x1a/0x28
  [<c039d558>] ei_start_xmit+0x74/0x270
  [<c053ecc9>] dev_hard_start_xmit+0x1a9/0x1f8
  [<c05499be>] __qdisc_run+0xb6/0x1a8
  [<c05403fd>] dev_queue_xmit+0x115/0x23c
  [<c059e441>] packet_sendmsg_spkt+0x195/0x1d0
  [<c05348cb>] sock_sendmsg+0xcf/0xf0
  [<c0534c8a>] sys_sendto+0xb6/0xf0
  [<c0535e07>] sys_socketcall+0x11f/0x194
  [<c010336f>] syscall_call+0x7/0xb
irq event stamp: 8667
hardirqs last  enabled at (8666): [<c05b18b1>] _spin_unlock_irqrestore+0x3d/0x48
hardirqs last disabled at (8667): [<c0103553>] common_interrupt+0x1b/0x2c
softirqs last  enabled at (8632): [<c011f23b>] __do_softirq+0x97/0xa8
softirqs last disabled at (8660): [<c0540323>] dev_queue_xmit+0x3b/0x23c

other info that might help us debug this:
1 lock held by dhclient/1952:
 #0:  (&dev->_xmit_lock){-+..}, at: [<c054993f>] __qdisc_run+0x37/0x1a8

stack backtrace:
 [<c0103b3e>] show_trace+0x16/0x1c
 [<c010412a>] dump_stack+0x1a/0x20
 [<c0132037>] print_usage_bug+0x1d7/0x1e4
 [<c0132802>] mark_lock+0x432/0x548
 [<c0133542>] __lock_acquire+0x53e/0xc68
 [<c0133f5b>] lock_acquire+0x57/0x74
 [<c05b15c2>] _spin_lock+0x1a/0x28
 [<c039d78d>] ei_interrupt+0x39/0x32c
 [<c013b150>] handle_IRQ_event+0x24/0x58
 [<c013c4e4>] handle_level_irq+0x6c/0xd0
 [<c0104ed1>] do_IRQ+0x55/0xa8
 [<c010355d>] common_interrupt+0x25/0x2c
 [<c013b957>] enable_irq+0x4b/0x9c
 [<c039d5f3>] ei_start_xmit+0x10f/0x270
 [<c053ecc9>] dev_hard_start_xmit+0x1a9/0x1f8
 [<c05499be>] __qdisc_run+0xb6/0x1a8
 [<c05403fd>] dev_queue_xmit+0x115/0x23c
 [<c059e441>] packet_sendmsg_spkt+0x195/0x1d0
 [<c05348cb>] sock_sendmsg+0xcf/0xf0
 [<c0534c8a>] sys_sendto+0xb6/0xf0
 [<c0535e07>] sys_socketcall+0x11f/0x194
 [<c010336f>] syscall_call+0x7/0xb
kobject_add failed for vcs1 with -EEXIST, don't try to register things with the same name in the same directory.
 [<c0103b3e>] show_trace+0x16/0x1c
 [<c010412a>] dump_stack+0x1a/0x20
 [<c02c9774>] kobject_add+0x114/0x1b4
 [<c037455f>] class_device_add+0xb3/0x484
 [<c0374943>] class_device_register+0x13/0x18
 [<c03749d2>] class_device_create+0x8a/0xbc
 [<c032d016>] vcs_make_devfs+0x26/0x54
 [<c0332bd9>] con_open+0x61/0x88
 [<c0327e7f>] tty_open+0x16f/0x348
 [<c0164507>] chrdev_open+0x63/0x168
 [<c015a634>] __dentry_open+0x8c/0x164
 [<c015a790>] nameidata_to_filp+0x30/0x3c
 [<c015a7d7>] do_filp_open+0x3b/0x44
 [<c015a81b>] do_sys_open+0x3b/0xc4
 [<c015a8cf>] sys_open+0x13/0x18
 [<c010336f>] syscall_call+0x7/0xb
kobject_add failed for vcsa1 with -EEXIST, don't try to register things with the same name in the same directory.
 [<c0103b3e>] show_trace+0x16/0x1c
 [<c010412a>] dump_stack+0x1a/0x20
 [<c02c9774>] kobject_add+0x114/0x1b4
 [<c037455f>] class_device_add+0xb3/0x484
 [<c0374943>] class_device_register+0x13/0x18
 [<c03749d2>] class_device_create+0x8a/0xbc
 [<c032d03c>] vcs_make_devfs+0x4c/0x54
 [<c0332bd9>] con_open+0x61/0x88
 [<c0327e7f>] tty_open+0x16f/0x348
 [<c0164507>] chrdev_open+0x63/0x168
 [<c015a634>] __dentry_open+0x8c/0x164
 [<c015a790>] nameidata_to_filp+0x30/0x3c
 [<c015a7d7>] do_filp_open+0x3b/0x44
 [<c015a81b>] do_sys_open+0x3b/0xc4
 [<c015a8cf>] sys_open+0x13/0x18
 [<c010336f>] syscall_call+0x7/0xb

Re: linux-2.6.17-mm6: strange kobject message

[Arjan van de Ven]

On Fri, 2006-07-07 at 12:59 +0400, Paul Drynoff wrote:
> Here is dmesg which I got during boot,
> the first part not interesting I already reported about it,
> and I don't remember one of two things: Arjan van de Ven's patch was
> lost or not good enough. 

it didn't make -mm6, but got added later...

Re: linux-2.6.17-mm6: strange kobject message

[Andrew Morton]

On Fri, 7 Jul 2006 12:59:42 +0400
Paul Drynoff <pauldrynoff@gmail.com> wrote:

> Here is dmesg which I got during boot,
> the first part not interesting I already reported about it,
> and I don't remember one of two things: Arjan van de Ven's patch was
> lost or not good enough. The second part is related to kobject,
> I'm not sure is it normal when kobject tell about -EEXIST and print stack?
> Note that this is happened only once per 100 normal booting, I mean the second part.
> 
> =================================
> [ INFO: inconsistent lock state ]
> ---------------------------------
> inconsistent {hardirq-on-W} -> {in-hardirq-W} usage.
> dhclient/1952 [HC1[1]:SC0[1]:HE0:SE0] takes:
>  (&ei_local->page_lock){+...}, at: [<c039d78d>] ei_interrupt+0x39/0x32c
> {hardirq-on-W} state was registered at:
>   [<c0133f5b>] lock_acquire+0x57/0x74
>   [<c05b15c2>] _spin_lock+0x1a/0x28
>   [<c039d558>] ei_start_xmit+0x74/0x270
>   [<c053ecc9>] dev_hard_start_xmit+0x1a9/0x1f8
>   [<c05499be>] __qdisc_run+0xb6/0x1a8
>   [<c05403fd>] dev_queue_xmit+0x115/0x23c
>   [<c059e441>] packet_sendmsg_spkt+0x195/0x1d0
>   [<c05348cb>] sock_sendmsg+0xcf/0xf0
>   [<c0534c8a>] sys_sendto+0xb6/0xf0
>   [<c0535e07>] sys_socketcall+0x11f/0x194
>   [<c010336f>] syscall_call+0x7/0xb
> irq event stamp: 8667
> hardirqs last  enabled at (8666): [<c05b18b1>] _spin_unlock_irqrestore+0x3d/0x48
> hardirqs last disabled at (8667): [<c0103553>] common_interrupt+0x1b/0x2c
> softirqs last  enabled at (8632): [<c011f23b>] __do_softirq+0x97/0xa8
> softirqs last disabled at (8660): [<c0540323>] dev_queue_xmit+0x3b/0x23c
> 
> other info that might help us debug this:
> 1 lock held by dhclient/1952:
>  #0:  (&dev->_xmit_lock){-+..}, at: [<c054993f>] __qdisc_run+0x37/0x1a8
> 
> stack backtrace:
>  [<c0103b3e>] show_trace+0x16/0x1c
>  [<c010412a>] dump_stack+0x1a/0x20
>  [<c0132037>] print_usage_bug+0x1d7/0x1e4
>  [<c0132802>] mark_lock+0x432/0x548
>  [<c0133542>] __lock_acquire+0x53e/0xc68
>  [<c0133f5b>] lock_acquire+0x57/0x74
>  [<c05b15c2>] _spin_lock+0x1a/0x28
>  [<c039d78d>] ei_interrupt+0x39/0x32c
>  [<c013b150>] handle_IRQ_event+0x24/0x58
>  [<c013c4e4>] handle_level_irq+0x6c/0xd0
>  [<c0104ed1>] do_IRQ+0x55/0xa8
>  [<c010355d>] common_interrupt+0x25/0x2c
>  [<c013b957>] enable_irq+0x4b/0x9c
>  [<c039d5f3>] ei_start_xmit+0x10f/0x270
>  [<c053ecc9>] dev_hard_start_xmit+0x1a9/0x1f8
>  [<c05499be>] __qdisc_run+0xb6/0x1a8
>  [<c05403fd>] dev_queue_xmit+0x115/0x23c
>  [<c059e441>] packet_sendmsg_spkt+0x195/0x1d0
>  [<c05348cb>] sock_sendmsg+0xcf/0xf0
>  [<c0534c8a>] sys_sendto+0xb6/0xf0
>  [<c0535e07>] sys_socketcall+0x11f/0x194
>  [<c010336f>] syscall_call+0x7/0xb

hm. 
ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.17/2.6.17-mm6/broken-out/lockdep-annotate-8390c-disable_irq.patch
didn't work.


> kobject_add failed for vcs1 with -EEXIST, don't try to register things with the same name in the same directory.
>  [<c0103b3e>] show_trace+0x16/0x1c
>  [<c010412a>] dump_stack+0x1a/0x20
>  [<c02c9774>] kobject_add+0x114/0x1b4
>  [<c037455f>] class_device_add+0xb3/0x484
>  [<c0374943>] class_device_register+0x13/0x18
>  [<c03749d2>] class_device_create+0x8a/0xbc
>  [<c032d016>] vcs_make_devfs+0x26/0x54
>  [<c0332bd9>] con_open+0x61/0x88
>  [<c0327e7f>] tty_open+0x16f/0x348
>  [<c0164507>] chrdev_open+0x63/0x168
>  [<c015a634>] __dentry_open+0x8c/0x164
>  [<c015a790>] nameidata_to_filp+0x30/0x3c
>  [<c015a7d7>] do_filp_open+0x3b/0x44
>  [<c015a81b>] do_sys_open+0x3b/0xc4
>  [<c015a8cf>] sys_open+0x13/0x18
>  [<c010336f>] syscall_call+0x7/0xb
> kobject_add failed for vcsa1 with -EEXIST, don't try to register things with the same name in the same directory.

We've seen this reported a couple of times before.  It could be a race in
the tty layer where a newly-added vc has the same index as a going-away
one which still has its sysfs file.  Or it could be something else :(

Once someone comes up with a way to reproduce it, we'll fix it though.

Re: linux-2.6.17-mm6: strange kobject message

[Arjan van de Ven]

On Fri, 2006-07-07 at 02:24 -0700, Andrew Morton wrote:

> hm. 
> ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.17/2.6.17-mm6/broken-out/lockdep-annotate-8390c-disable_irq.patch
> didn't work.

-mm6 only had part 1; you also have part 2 now which should fix this one

> We've seen this reported a couple of times before.  It could be a race in
> the tty layer where a newly-added vc has the same index as a going-away
> one which still has its sysfs file.  Or it could be something else :(

that'd be a bug in the tty layer; the VC shouldn't be allowed to go away
until the sysfs file is gone (basic sysfs refcounting rules), and any
person keeping such a file open can delay that.
Now I can believe the tty layer having, ehm, suboptimal
refcounting/locking; I believe Alan is still trying to get it sane....

Re: linux-2.6.17-mm6: strange kobject message

[Andrew Morton]

On Fri, 07 Jul 2006 11:29:12 +0200
Arjan van de Ven <arjan@infradead.org> wrote:

> On Fri, 2006-07-07 at 02:24 -0700, Andrew Morton wrote:
> 
> > hm. 
> > ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.17/2.6.17-mm6/broken-out/lockdep-annotate-8390c-disable_irq.patch
> > didn't work.
> 
> -mm6 only had part 1; you also have part 2 now which should fix this one

OK, here it is:

From: Arjan van de Ven <arjan@linux.intel.com>

The ne2000 drivers use disable_irq as a poor mans locking construct; make
sure lockdep knows about these.

NOTE NOTE: the ne2000 driver calls these *from interrupt context*.  That's
a new situation that needs to be analyzed for correctness still; it feels
really wrong to me (but then again so does disable_irq() tricks in general)

Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Cc: "David S. Miller" <davem@davemloft.net>
Cc: Jeff Garzik <jeff@garzik.org>
Signed-off-by: Andrew Morton <akpm@osdl.org>
---

 drivers/net/8390.c |   10 +++++-----
 1 files changed, 5 insertions(+), 5 deletions(-)

diff -puN drivers/net/8390.c~lockdep-annotate-8390c-disable_irq-2 drivers/net/8390.c
--- a/drivers/net/8390.c~lockdep-annotate-8390c-disable_irq-2
+++ a/drivers/net/8390.c
@@ -299,7 +299,7 @@ static int ei_start_xmit(struct sk_buff 
 	 *	Slow phase with lock held.
 	 */
 	 
-	disable_irq_nosync(dev->irq);
+	disable_irq_nosync_lockdep(dev->irq);
 	
 	spin_lock(&ei_local->page_lock);
 	
@@ -338,7 +338,7 @@ static int ei_start_xmit(struct sk_buff 
 		netif_stop_queue(dev);
 		outb_p(ENISR_ALL, e8390_base + EN0_IMR);
 		spin_unlock(&ei_local->page_lock);
-		enable_irq(dev->irq);
+		enable_irq_lockdep(dev->irq);
 		ei_local->stat.tx_errors++;
 		return 1;
 	}
@@ -379,7 +379,7 @@ static int ei_start_xmit(struct sk_buff 
 	outb_p(ENISR_ALL, e8390_base + EN0_IMR);
 	
 	spin_unlock(&ei_local->page_lock);
-	enable_irq(dev->irq);
+	enable_irq_lockdep(dev->irq);
 
 	dev_kfree_skb (skb);
 	ei_local->stat.tx_bytes += send_length;
@@ -505,9 +505,9 @@ irqreturn_t ei_interrupt(int irq, void *
 #ifdef CONFIG_NET_POLL_CONTROLLER
 void ei_poll(struct net_device *dev)
 {
-	disable_irq(dev->irq);
+	disable_irq_lockdep(dev->irq);
 	ei_interrupt(dev->irq, dev, NULL);
-	enable_irq(dev->irq);
+	enable_irq_lockdep(dev->irq);
 }
 #endif
 
_