inconsistent lock state on call to kmem_cache_zalloc()

[arvid.brodin@enea.com (Arvid Brodin)]

On a call to kmem_cache_zalloc(), I get this:

=================================
[ INFO: inconsistent lock state ]
2.6.37 #116
---------------------------------
inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
khubd/133 [HC0[0]:SC0[0]:HE1:SE1] takes:
 (&(&priv->lock)->rlock){?.-...}, at: [<9017a508>] isp1760_urb_enqueue+0x24c/0x3e4
{IN-HARDIRQ-W} state was registered at:
  [<90043476>] lock_acquire+0x3a/0x48
  [<90236210>] _raw_spin_lock_irqsave+0x28/0x50
  [<9017a7ac>] isp1760_irq+0x44/0x3b4
  [<9016ffec>] usb_hcd_irq+0x68/0x70
...

And I cannot understand why. (I'm also unsure about the syntax - what does
"IN-HARDIRQ-W" and "HARDIRQ-ON-W" mean?)

Background:

I have an interrupt routine isp1760_irq() that calls
	spin_lock(&priv->lock)
	...
	spin_unlock(&priv->lock)

I also take this lock in isp1760_urb_enqueue() mentioned in the printout. I
believe this function gets called by the USB core when an urb should be
transferred. isp1760_urb_enqueue() uses

	spin_lock_irqsave(&priv->lock, spinflags);
	...
	spin_unlock_irqrestore(&priv->lock, spinflags);

isp1760_urb_enqueue() also calls kmem_cache_zalloc(); this is what apparently
triggers the printout above (the lock have already been successfully taken).

The call to kmem_cache_zalloc() never returns; the printk() text on the line
after is never displayed and the system locks up. The printk() om the line
before displays.

I also get an additional BUG:

BUG: spinlock lockup on CPU#0, khubd/133, 93dcc138
Call trace:
 [<9001d370>] dump_stack+0x18/0x20
 [<9012e7aa>] do_raw_spin_lock+0x9a/0xc8
 [<9023622a>] _raw_spin_lock_irqsave+0x42/0x50
 [<9017a7ac>] isp1760_irq+0x44/0x3b4
 [<9016ffec>] usb_hcd_irq+0x68/0x70
 [<9004b2fc>] handle_IRQ_event+0x16/0x92
 [<9004cbec>] handle_level_irq+0xb0/0xc8
 [<9001ad28>] demux_eic_irq+0x38/0x50
 [<9001ac36>] do_IRQ+0x36/0x5c
 [<90019428>] irq_level0+0x18/0x60
 [<9006aa96>] kmem_cache_alloc+0x4a/0x90
 [<9017a59c>] isp1760_urb_enqueue+0x2e0/0x3e4
 [<90170e54>] usb_hcd_submit_urb+0x6d4/0x758
 [<90171186>] usb_submit_urb+0x1ce/0x1e0
 [<901718aa>] usb_start_wait_urb+0x32/0x80
 [<90171bc4>] usb_control_msg+0xc0/0xd8
 [<9016d6ac>] hub_port_init+0x218/0x528
 [<9016e672>] hub_thread+0x5aa/0xa38
 [<900358c6>] kthread+0x58/0x62
 [<90027c4a>] do_exit+0x0/0x43e

which seems very weird to me, since it looks like isp1760_irq() gets called
even though I thought I had disabled interrupts with spin_lock_irqsave() in
isp1760_urb_enqueue().

Obviously I have not understood the locking in the kernel. What have I done
wrong here?

Thanks,
Arvid Brodin
Enea Services Stockholm AB