While attempting to configure a new USB modem, the following locking problem occurred. In addition,
shortly after this problem occurred, the computer froze. The log data starts at the point that
usbserial was loaded and contains everything that was written to disk before the machine locked up.
Some info may be missing from the end of the stack dump.
The system is an HP laptop running an x86_64 system. NetworkManager was used to initiate the modem
connection.
Dump Contents:
usbcore: registered new interface driver usbserial
drivers/usb/serial/usb-serial.c: USB Serial support registered for generic
usbserial_generic 2-5:1.0: Generic device with no bulk out, not allowed.
usbserial_generic: probe of 2-5:1.0 failed with error -5
usbserial_generic 2-5:1.1: generic converter detected
usb 2-5: generic converter now attached to ttyUSB0
usbcore: registered new interface driver usbserial_generic
drivers/usb/serial/usb-serial.c: USB Serial Driver core
ifup: modem1
interface modem1 is up
Plugin passwordfd.so loaded.
PPP generic driver version 2.4.2
pppd 2.4.4 started by root, uid 0
=================================
[ INFO: inconsistent lock state ]
2.6.23-Linus-g5a34417f-dirty #27
---------------------------------
inconsistent {hardirq-on-W} -> {in-hardirq-W} usage.
swapper/0 [HC1[1]:SC0[0]:HE0:SE1] takes:
(&port->lock){+...}, at: [<ffffffff883f38bd>] usb_serial_generic_read_bulk_callback+0x104/0x179
[usbserial]
{hardirq-on-W} state was registered at:
[<ffffffff8024eb9e>] mark_lock+0x8b/0x49a
[<ffffffff8024fbab>] __lock_acquire+0x517/0xd4b
[<ffffffff883f3b7f>] usb_serial_generic_write+0x8a/0x24f [usbserial]
[<ffffffff80250464>] lock_acquire+0x85/0xa9
[<ffffffff883f3b7f>] usb_serial_generic_write+0x8a/0x24f [usbserial]
[<ffffffff803ea2f7>] _spin_lock_bh+0x34/0x41
[<ffffffff883f3b7f>] usb_serial_generic_write+0x8a/0x24f [usbserial]
[<ffffffff883f162e>] serial_write+0xb2/0xc1 [usbserial]
[<ffffffff80340635>] write_chan+0x292/0x317
[<ffffffff8022c1ce>] default_wake_function+0x0/0xf
[<ffffffff8033dd45>] tty_write+0x102/0x20b
[<ffffffff8033ddb0>] tty_write+0x16d/0x20b
[<ffffffff803403a3>] write_chan+0x0/0x317
[<ffffffff8028ef15>] vfs_write+0xae/0x137
[<ffffffff8028f47e>] sys_write+0x47/0x70
[<ffffffff8020c2fa>] tracesys+0xdc/0xe1
[<ffffffffffffffff>] 0xffffffffffffffff
irq event stamp: 2973292
hardirqs last enabled at (2973291): [<ffffffff8020adc6>] default_idle+0x35/0x51
hardirqs last disabled at (2973292): [<ffffffff803e9d54>] trace_hardirqs_off_thunk+0x35/0x37
softirqs last enabled at (2973288): [<ffffffff80237add>] __do_softirq+0xe1/0xed
softirqs last disabled at (2973281): [<ffffffff8020d43c>] call_softirq+0x1c/0x28
other info that might help us debug this:
no locks held by swapper/0.
stack backtrace:
Call Trace:
<IRQ> [<ffffffff8024e39d>] print_usage_bug+0x162/0x173
[<ffffffff8024ebee>] mark_lock+0xdb/0x49a
[<ffffffff8024fb3c>] __lock_acquire+0x4a8/0xd4b
[<ffffffff883f38bd>] :usbserial:usb_serial_generic_read_bulk_callback+0x104/0x179
[<ffffffff80250464>] lock_acquire+0x85/0xa9
[<ffffffff883f38bd>] :usbserial:usb_serial_generic_read_bulk_callback+0x104/0x179
[<ffffffff803ea2b6>] _spin_lock+0x2f/0x3c
[<ffffffff883f38bd>] :usbserial:usb_serial_generic_read_bulk_callback+0x104/0x179
[<ffffffff880c516b>] :usbcore:usb_hcd_giveback_urb+0x84/0x
[<ffffffff88105578>] :ohci_hcd:finish_urb+0x74/0xb6
[<ffffffff881055fc>] :ohci_hcd:takeback_td+0x42/0xb5
[<ffffffff8810579a>] :ohci_hcd:dl_done_list+0x12b/0x13c
[<ffffffff88107ce3>] :ohci_hcd:ohci_irq+0x19a/0x2d6
[<ffffffff880c5441>] :usbcore:usb_hcd_irq+0x2c/0x5d
[<ffffffff802663b5>] handle_IRQ_event+0x20/0x55
[<ffffffff80267767>] handle_fasteoi_irq+0x9c/0xdc
[<ffffffff8020ad91>] default_idle+0x0/0x51
[<ffffffff8020f475>] do_IRQ+0x70/0xd7
[<ffffffff8020ad91>] default_idle+0x0/0x51
[<ffffffff8020c706>] ret_from_intr+0x0/0xf
<EOI> [<ffffffff8020adc8>] default_idle+0x37/0x51
[<ffffffff8020adc6>] default_idle+0x35/0x51
[<ffffffff8020ae80>] cpu_idle+0x9e/0xd5
[<ffffffff8021aae3>] start_secondary+0x34c/0x35d
Thanks,
Larry
On Fri, 19 Oct 2007, Larry Finger wrote:
> While attempting to configure a new USB modem, the following locking
> problem occurred. In addition, shortly after this problem occurred, the
> computer froze. The log data starts at the point that usbserial was
> loaded and contains everything that was written to disk before the
> machine locked up. Some info may be missing from the end of the stack
> dump.
I guess this one is needed.
From: Jiri Kosina <[email protected]>
USB: usbserial - fix potential deadlock between write() and irq
usb_serial_generic_write() doesn't disable interrupts when taking port->lock,
and could therefore deadlock with usb_serial_generic_read_bulk_callback()
being called from interrupt, taking the same lock. Fix it.
Signed-off-by: Jiri Kosina <[email protected]>
diff --git a/drivers/usb/serial/generic.c b/drivers/usb/serial/generic.c
index 88a2c7d..6f8d712 100644
--- a/drivers/usb/serial/generic.c
+++ b/drivers/usb/serial/generic.c
@@ -208,14 +208,15 @@ int usb_serial_generic_write(struct usb_serial_port *port, const unsigned char *
/* only do something if we have a bulk out endpoint */
if (serial->num_bulk_out) {
- spin_lock_bh(&port->lock);
+ unsigned long flags;
+ spin_lock_irqsave(&port->lock, flags);
if (port->write_urb_busy) {
spin_unlock_bh(&port->lock);
dbg("%s - already writing", __FUNCTION__);
return 0;
}
port->write_urb_busy = 1;
- spin_unlock_bh(&port->lock);
+ spin_unlock_irqrestore(&port->lock, flags);
count = (count > port->bulk_out_size) ? port->bulk_out_size : count;
Jiri Kosina wrote:
> On Fri, 19 Oct 2007, Larry Finger wrote:
>
>> While attempting to configure a new USB modem, the following locking
>> problem occurred. In addition, shortly after this problem occurred, the
>> computer froze. The log data starts at the point that usbserial was
>> loaded and contains everything that was written to disk before the
>> machine locked up. Some info may be missing from the end of the stack
>> dump.
>
> I guess this one is needed.
>
>
> From: Jiri Kosina <[email protected]>
>
> USB: usbserial - fix potential deadlock between write() and irq
>
> usb_serial_generic_write() doesn't disable interrupts when taking port->lock,
> and could therefore deadlock with usb_serial_generic_read_bulk_callback()
> being called from interrupt, taking the same lock. Fix it.
>
> Signed-off-by: Jiri Kosina <[email protected]>
>
Yes, this patch did fix the locking problem.
Thanks,
Larry
Jiri Kosina wrote:
> On Fri, 19 Oct 2007, Larry Finger wrote:
>
>> While attempting to configure a new USB modem, the following locking
>> problem occurred. In addition, shortly after this problem occurred, the
>> computer froze. The log data starts at the point that usbserial was
>> loaded and contains everything that was written to disk before the
>> machine locked up. Some info may be missing from the end of the stack
>> dump.
>
> I guess this one is needed.
>
>
> From: Jiri Kosina <[email protected]>
>
> USB: usbserial - fix potential deadlock between write() and irq
>
> usb_serial_generic_write() doesn't disable interrupts when taking port->lock,
> and could therefore deadlock with usb_serial_generic_read_bulk_callback()
> being called from interrupt, taking the same lock. Fix it.
>
> Signed-off-by: Jiri Kosina <[email protected]>
>
As I said earlier, the lock problem went away; however, I get the following two kernel warnings:
WARNING: at kernel/sched.c:3475 sub_preempt_count()
Call Trace:
[<ffffffff8022df50>] sub_preempt_count+0x7e/0x91
[<ffffffff80237eb9>] local_bh_enable_ip+0x91/0xf5
[<ffffffff803eaaa8>] _spin_unlock_bh+0x39/0x3e
[<ffffffff88405409>] :ppp_generic:ppp_channel_push+0x72/0xad
[<ffffffff88406528>] :ppp_generic:ppp_write+0x10f/0x121
[<ffffffff8028f75d>] vfs_write+0xae/0x137
[<ffffffff8028fcc6>] sys_write+0x47/0x70
[<ffffffff8020c2fa>] tracesys+0xdc/0xe1
PPP BSD Compression module registered
PPP Deflate Compression module registered
WARNING: at kernel/softirq.c:139 local_bh_enable()
Call Trace:
[<ffffffff80237d82>] local_bh_enable+0x8f/0x135
[<ffffffff8038f9ec>] dev_queue_xmit+0x2a6/0x2d2
[<ffffffff803ab2be>] ip_finish_output+0x221/0x24f
[<ffffffff803ab5d0>] ip_output+0x53/0x55
[<ffffffff803a9df5>] ip_push_pending_frames+0x309/0x3ed
[<ffffffff803c5f88>] udp_push_pending_frames+0x2d7/0x33f
[<ffffffff803c70e9>] udp_sendmsg+0x4d5/0x61d
[<ffffffff80248c99>] lock_hrtimer_base+0x25/0x4a
[<ffffffff803cccce>] inet_sendmsg+0x46/0x53
[<ffffffff80381ca3>] sock_sendmsg+0xdf/0xf8
[<ffffffff80248e8f>] hrtimer_start+0x102/0x114
[<ffffffff8024653c>] autoremove_wake_function+0x0/0x38
[<ffffffff8020bb85>] do_notify_resume+0x68e/0x7ac
[<ffffffff803ea5cb>] trace_hardirqs_on_thunk+0x35/0x3a
[<ffffffff803826b4>] move_addr_to_kernel+0x40/0x49
[<ffffffff803827db>] sys_sendto+0x11e/0x143
[<ffffffff8020bf5d>] sys_rt_sigreturn+0x2a6/0x389
[<ffffffff80265072>] audit_syscall_entry+0x148/0x17e
[<ffffffff8020c2fa>] tracesys+0xdc/0xe1
The second is complaining that interrupts are disabled, and may be related.
Larry
On Fri, 19 Oct 2007, Larry Finger wrote:
> As I said earlier, the lock problem went away; however, I get the
> following two kernel warnings:
That's because I messed up the patch, sorry. The one below should work
better.
From: Jiri Kosina <[email protected]>
USB: usbserial - fix potential deadlock between write() and IRQ
usb_serial_generic_write() doesn't disable interrupts when taking port->lock,
and could therefore deadlock with usb_serial_generic_read_bulk_callback()
being called from interrupt, taking the same lock. Fix it.
Signed-off-by: Jiri Kosina <[email protected]>
diff --git a/drivers/usb/serial/generic.c b/drivers/usb/serial/generic.c
index 88a2c7d..9eb4a65 100644
--- a/drivers/usb/serial/generic.c
+++ b/drivers/usb/serial/generic.c
@@ -208,14 +208,15 @@ int usb_serial_generic_write(struct usb_serial_port *port, const unsigned char *
/* only do something if we have a bulk out endpoint */
if (serial->num_bulk_out) {
- spin_lock_bh(&port->lock);
+ unsigned long flags;
+ spin_lock_irqsave(&port->lock, flags);
if (port->write_urb_busy) {
- spin_unlock_bh(&port->lock);
+ spin_unlock_irqrestore(&port->lock, flags);
dbg("%s - already writing", __FUNCTION__);
return 0;
}
port->write_urb_busy = 1;
- spin_unlock_bh(&port->lock);
+ spin_unlock_irqrestore(&port->lock, flags);
count = (count > port->bulk_out_size) ? port->bulk_out_size : count;
Jiri Kosina wrote:
> On Fri, 19 Oct 2007, Larry Finger wrote:
>
>> As I said earlier, the lock problem went away; however, I get the
>> following two kernel warnings:
>
> That's because I messed up the patch, sorry. The one below should work
> better.
>
>
>
> From: Jiri Kosina <[email protected]>
>
> USB: usbserial - fix potential deadlock between write() and IRQ
>
> usb_serial_generic_write() doesn't disable interrupts when taking port->lock,
> and could therefore deadlock with usb_serial_generic_read_bulk_callback()
> being called from interrupt, taking the same lock. Fix it.
>
> Signed-off-by: Jiri Kosina <[email protected]>
It does work better. With it, I was able to make a dial-up connection and send pings over it.
Larry
On Sat, Oct 20, 2007 at 12:05:19AM +0200, Jiri Kosina wrote:
> On Fri, 19 Oct 2007, Larry Finger wrote:
>
> > As I said earlier, the lock problem went away; however, I get the
> > following two kernel warnings:
>
> That's because I messed up the patch, sorry. The one below should work
> better.
>
>
>
> From: Jiri Kosina <[email protected]>
>
> USB: usbserial - fix potential deadlock between write() and IRQ
Jiri, thanks a lot for the fix, I'll queue it up.
greg k-h
This is a note to let you know that I've just added the patch titled
Subject: USB: usbserial - fix potential deadlock between write() and IRQ
to my gregkh-2.6 tree. Its filename is
usb-usbserial-fix-potential-deadlock-between-write-and-irq.patch
This tree can be found at
http://www.kernel.org/pub/linux/kernel/people/gregkh/gregkh-2.6/patches/
>From [email protected] Wed Oct 24 14:28:04 2007
From: Jiri Kosina <[email protected]>
Date: Sat, 20 Oct 2007 00:05:19 +0200 (CEST)
Subject: USB: usbserial - fix potential deadlock between write() and IRQ
To: Larry Finger <[email protected]>
Cc: LKML <[email protected]>, Greg Kroah-Hartman <[email protected]>, [email protected]
Message-ID: <[email protected]>
From: Jiri Kosina <[email protected]>
USB: usbserial - fix potential deadlock between write() and IRQ
usb_serial_generic_write() doesn't disable interrupts when taking port->lock,
and could therefore deadlock with usb_serial_generic_read_bulk_callback()
being called from interrupt, taking the same lock. Fix it.
Signed-off-by: Jiri Kosina <[email protected]>
Acked-by: Larry Finger <[email protected]>
Signed-off-by: Greg Kroah-Hartman <[email protected]>
---
drivers/usb/serial/generic.c | 7 ++++---
1 file changed, 4 insertions(+), 3 deletions(-)
--- a/drivers/usb/serial/generic.c
+++ b/drivers/usb/serial/generic.c
@@ -208,14 +208,15 @@ int usb_serial_generic_write(struct usb_
/* only do something if we have a bulk out endpoint */
if (serial->num_bulk_out) {
- spin_lock_bh(&port->lock);
+ unsigned long flags;
+ spin_lock_irqsave(&port->lock, flags);
if (port->write_urb_busy) {
- spin_unlock_bh(&port->lock);
+ spin_unlock_irqrestore(&port->lock, flags);
dbg("%s - already writing", __FUNCTION__);
return 0;
}
port->write_urb_busy = 1;
- spin_unlock_bh(&port->lock);
+ spin_unlock_irqrestore(&port->lock, flags);
count = (count > port->bulk_out_size) ? port->bulk_out_size : count;
Patches currently in gregkh-2.6 which might be from [email protected] are
usb/usb-usbserial-fix-potential-deadlock-between-write-and-irq.patch