Re: WARNINGs in usb-serial.c

Re: WARNINGs in usb-serial.c

[Greg KH]

On Thu, Sep 03, 2009 at 04:13:34PM +0200, Miklos Szeredi wrote:
> I get the following warnings in 2.6.31-rc.  A lot of them:
> 
> WARNING: at drivers/usb/serial/usb-serial.c:414 serial_write_room+0x59/0x6e [usbserial]()
> WARNING: at drivers/usb/serial/usb-serial.c:401 serial_write+0x77/0x9d [usbserial]()
> 
> This is a huawei-3565 modem.
> 
> The messages don't seem to hurt, but there's lot of trouble with this
> gadget.  Sometimes it just doesn't work after a while and a reboot is
> needed.  Sometimes it hangs the kernel after suspend, etc.  Not sure
> if this is related to the warnings...

{sigh}

The tty layer changes are being a pain here :(

Alan Stern posted a set of patches to the linux-usb list to hopefully
address stuff like this, is there any way you could test them out to see
if they help or not?

thanks,

greg k-h

Re: WARNINGs in usb-serial.c

[Rafael J. Wysocki]

On Thursday 03 September 2009, Greg KH wrote:
> On Thu, Sep 03, 2009 at 04:13:34PM +0200, Miklos Szeredi wrote:
> > I get the following warnings in 2.6.31-rc.  A lot of them:
> > 
> > WARNING: at drivers/usb/serial/usb-serial.c:414 serial_write_room+0x59/0x6e [usbserial]()
> > WARNING: at drivers/usb/serial/usb-serial.c:401 serial_write+0x77/0x9d [usbserial]()
> > 
> > This is a huawei-3565 modem.
> > 
> > The messages don't seem to hurt, but there's lot of trouble with this
> > gadget.  Sometimes it just doesn't work after a while and a reboot is
> > needed.  Sometimes it hangs the kernel after suspend, etc.  Not sure
> > if this is related to the warnings...
> 
> {sigh}
> 
> The tty layer changes are being a pain here :(
> 
> Alan Stern posted a set of patches to the linux-usb list to hopefully
> address stuff like this, is there any way you could test them out to see
> if they help or not?

Do you have a pointer to the patches, please?  I need it for the regression list.

Rafael

Re: WARNINGs in usb-serial.c

[Greg KH]

On Thu, Sep 03, 2009 at 11:24:01PM +0200, Rafael J. Wysocki wrote:
> On Thursday 03 September 2009, Greg KH wrote:
> > On Thu, Sep 03, 2009 at 04:13:34PM +0200, Miklos Szeredi wrote:
> > > I get the following warnings in 2.6.31-rc.  A lot of them:
> > > 
> > > WARNING: at drivers/usb/serial/usb-serial.c:414 serial_write_room+0x59/0x6e [usbserial]()
> > > WARNING: at drivers/usb/serial/usb-serial.c:401 serial_write+0x77/0x9d [usbserial]()
> > > 
> > > This is a huawei-3565 modem.
> > > 
> > > The messages don't seem to hurt, but there's lot of trouble with this
> > > gadget.  Sometimes it just doesn't work after a while and a reboot is
> > > needed.  Sometimes it hangs the kernel after suspend, etc.  Not sure
> > > if this is related to the warnings...
> > 
> > {sigh}
> > 
> > The tty layer changes are being a pain here :(
> > 
> > Alan Stern posted a set of patches to the linux-usb list to hopefully
> > address stuff like this, is there any way you could test them out to see
> > if they help or not?
> 
> Do you have a pointer to the patches, please?  I need it for the regression list.

They were posted on the linux-usb mailing list, I'm still fighting my
patch queue to get them into my tree soon.

thanks,

greg k-h

Re: WARNINGs in usb-serial.c

[Miklos Szeredi]

On Thu, 3 Sep 2009, Greg KH wrote:
> On Thu, Sep 03, 2009 at 04:13:34PM +0200, Miklos Szeredi wrote:
> > I get the following warnings in 2.6.31-rc.  A lot of them:
> > 
> > WARNING: at drivers/usb/serial/usb-serial.c:414 serial_write_room+0x59/0x6e [usbserial]()
> > WARNING: at drivers/usb/serial/usb-serial.c:401 serial_write+0x77/0x9d [usbserial]()
> > 
> > This is a huawei-3565 modem.
> > 
> > The messages don't seem to hurt, but there's lot of trouble with this
> > gadget.  Sometimes it just doesn't work after a while and a reboot is
> > needed.  Sometimes it hangs the kernel after suspend, etc.  Not sure
> > if this is related to the warnings...
> 
> {sigh}
> 
> The tty layer changes are being a pain here :(
> 
> Alan Stern posted a set of patches to the linux-usb list to hopefully
> address stuff like this, is there any way you could test them out to see
> if they help or not?

Nope, it doesn't seem to help.  Still got the same warnings with the
patched kernel (latest git + ghk tree + usbserial patches).

Thanks,
Miklos


[ 1658.280527] ------------[ cut here ]------------
[ 1658.280546] WARNING: at drivers/usb/serial/usb-serial.c:421 serial_write_room+0x59/0x6e [usbserial]()
[ 1658.280552] Hardware name: 2007FUG
[ 1658.280556] Modules linked in: option usbserial usb_storage bnep rfcomm sco l2cap acpi_cpufreq nf_conntrack_netbios_ns microcode fuse iwl3945 iwlcore thinkpad_acpi mac80211 backlight btusb led_class bluetooth thermal ac battery processor button nsc_ircc irda crc_ccitt cfg80211 rfkill e1000e uinput [last unloaded: usbserial]
[ 1658.280629] Pid: 9, comm: events/0 Not tainted 2.6.31-rc8-gkh-00038-g37d0892-dirty #33
[ 1658.280634] Call Trace:
[ 1658.280650]  [<ffffffffa01ca72c>] ? serial_write_room+0x59/0x6e [usbserial]
[ 1658.280663]  [<ffffffff81041d0d>] warn_slowpath_common+0x7c/0xa9
[ 1658.280672]  [<ffffffff81041d4e>] warn_slowpath_null+0x14/0x16
[ 1658.280684]  [<ffffffffa01ca72c>] serial_write_room+0x59/0x6e [usbserial]
[ 1658.280695]  [<ffffffff811c273d>] tty_write_room+0x1d/0x1f
[ 1658.280702]  [<ffffffff811c0111>] process_echoes+0x59/0x289
[ 1658.280712]  [<ffffffff8131da65>] ? mutex_unlock+0xe/0x10
[ 1658.280720]  [<ffffffff811c2078>] n_tty_receive_buf+0xa28/0xebd
[ 1658.280731]  [<ffffffff81067ed8>] ? mark_held_locks+0x4d/0x6b
[ 1658.280740]  [<ffffffff8131fa88>] ? _spin_unlock_irqrestore+0x44/0x72
[ 1658.280748]  [<ffffffff8106814b>] ? trace_hardirqs_on_caller+0x10b/0x12f
[ 1658.280757]  [<ffffffff811c47ef>] flush_to_ldisc+0x12f/0x1d7
[ 1658.280767]  [<ffffffff810542f7>] worker_thread+0x234/0x350
[ 1658.280775]  [<ffffffff810542a0>] ? worker_thread+0x1dd/0x350
[ 1658.280783]  [<ffffffff811c46c0>] ? flush_to_ldisc+0x0/0x1d7
[ 1658.280791]  [<ffffffff81059226>] ? autoremove_wake_function+0x0/0x3d
[ 1658.280800]  [<ffffffff8106817c>] ? trace_hardirqs_on+0xd/0xf
[ 1658.280808]  [<ffffffff810540c3>] ? worker_thread+0x0/0x350
[ 1658.280815]  [<ffffffff81058e34>] kthread+0x94/0x9c
[ 1658.280824]  [<ffffffff8100c29a>] child_rip+0xa/0x20
[ 1658.280832]  [<ffffffff8100bc00>] ? restore_args+0x0/0x30
[ 1658.280839]  [<ffffffff81058da0>] ? kthread+0x0/0x9c
[ 1658.280846]  [<ffffffff8100c290>] ? child_rip+0x0/0x20
[ 1658.280851] ---[ end trace 644f4c2ff2fe597f ]---
[ 1658.280856] ------------[ cut here ]------------
[ 1658.280868] WARNING: at drivers/usb/serial/usb-serial.c:408 serial_write+0x77/0x9d [usbserial]()
[ 1658.280873] Hardware name: 2007FUG
[ 1658.280876] Modules linked in: option usbserial usb_storage bnep rfcomm sco l2cap acpi_cpufreq nf_conntrack_netbios_ns microcode fuse iwl3945 iwlcore thinkpad_acpi mac80211 backlight btusb led_class bluetooth thermal ac battery processor button nsc_ircc irda crc_ccitt cfg80211 rfkill e1000e uinput [last unloaded: usbserial]
[ 1658.280940] Pid: 9, comm: events/0 Tainted: G        W  2.6.31-rc8-gkh-00038-g37d0892-dirty #33
[ 1658.280945] Call Trace:
[ 1658.280957]  [<ffffffffa01ca7b8>] ? serial_write+0x77/0x9d [usbserial]
[ 1658.280966]  [<ffffffff81041d0d>] warn_slowpath_common+0x7c/0xa9
[ 1658.280974]  [<ffffffff81041d4e>] warn_slowpath_null+0x14/0x16
[ 1658.280986]  [<ffffffffa01ca7b8>] serial_write+0x77/0x9d [usbserial]
[ 1658.280994]  [<ffffffff811bc4b9>] tty_put_char+0x32/0x34
[ 1658.281002]  [<ffffffff811bff14>] do_output_char+0xb3/0x201
[ 1658.281016]  [<ffffffff811c0294>] process_echoes+0x1dc/0x289
[ 1658.281024]  [<ffffffff811c2078>] n_tty_receive_buf+0xa28/0xebd
[ 1658.281033]  [<ffffffff81067ed8>] ? mark_held_locks+0x4d/0x6b
[ 1658.281042]  [<ffffffff8131fa88>] ? _spin_unlock_irqrestore+0x44/0x72
[ 1658.281050]  [<ffffffff8106814b>] ? trace_hardirqs_on_caller+0x10b/0x12f
[ 1658.281059]  [<ffffffff811c47ef>] flush_to_ldisc+0x12f/0x1d7
[ 1658.281068]  [<ffffffff810542f7>] worker_thread+0x234/0x350
[ 1658.281103]  [<ffffffff810542a0>] ? worker_thread+0x1dd/0x350
[ 1658.281111]  [<ffffffff811c46c0>] ? flush_to_ldisc+0x0/0x1d7
[ 1658.281119]  [<ffffffff81059226>] ? autoremove_wake_function+0x0/0x3d
[ 1658.281128]  [<ffffffff8106817c>] ? trace_hardirqs_on+0xd/0xf
[ 1658.281136]  [<ffffffff810540c3>] ? worker_thread+0x0/0x350
[ 1658.281143]  [<ffffffff81058e34>] kthread+0x94/0x9c
[ 1658.281151]  [<ffffffff8100c29a>] child_rip+0xa/0x20
[ 1658.281159]  [<ffffffff8100bc00>] ? restore_args+0x0/0x30
[ 1658.281166]  [<ffffffff81058da0>] ? kthread+0x0/0x9c
[ 1658.281173]  [<ffffffff8100c290>] ? child_rip+0x0/0x20
[ 1658.281177] ---[ end trace 644f4c2ff2fe5980 ]---
[ 1658.281189] ------------[ cut here ]------------
[ 1658.281201] WARNING: at drivers/usb/serial/usb-serial.c:408 serial_write+0x77/0x9d [usbserial]()
[ 1658.281229] Hardware name: 2007FUG
[ 1658.281232] Modules linked in: option usbserial usb_storage bnep rfcomm sco l2cap acpi_cpufreq nf_conntrack_netbios_ns microcode fuse iwl3945 iwlcore thinkpad_acpi mac80211 backlight btusb led_class bluetooth thermal ac battery processor button nsc_ircc irda crc_ccitt cfg80211 rfkill e1000e uinput [last unloaded: usbserial]
[ 1658.281297] Pid: 9, comm: events/0 Tainted: G        W  2.6.31-rc8-gkh-00038-g37d0892-dirty #33
[ 1658.281302] Call Trace:
[ 1658.281314]  [<ffffffffa01ca7b8>] ? serial_write+0x77/0x9d [usbserial]
[ 1658.281323]  [<ffffffff81041d0d>] warn_slowpath_common+0x7c/0xa9
[ 1658.281332]  [<ffffffff81041d4e>] warn_slowpath_null+0x14/0x16
[ 1658.281344]  [<ffffffffa01ca7b8>] serial_write+0x77/0x9d [usbserial]
[ 1658.281352]  [<ffffffff811bc4b9>] tty_put_char+0x32/0x34
[ 1658.281359]  [<ffffffff811bff21>] do_output_char+0xc0/0x201
[ 1658.281367]  [<ffffffff811c0294>] process_echoes+0x1dc/0x289
[ 1658.281375]  [<ffffffff811c2078>] n_tty_receive_buf+0xa28/0xebd
[ 1658.281384]  [<ffffffff81067ed8>] ? mark_held_locks+0x4d/0x6b
[ 1658.281393]  [<ffffffff8131fa88>] ? _spin_unlock_irqrestore+0x44/0x72
[ 1658.281402]  [<ffffffff8106814b>] ? trace_hardirqs_on_caller+0x10b/0x12f
[ 1658.281410]  [<ffffffff811c47ef>] flush_to_ldisc+0x12f/0x1d7
[ 1658.281419]  [<ffffffff810542f7>] worker_thread+0x234/0x350
[ 1658.281426]  [<ffffffff810542a0>] ? worker_thread+0x1dd/0x350
[ 1658.281434]  [<ffffffff811c46c0>] ? flush_to_ldisc+0x0/0x1d7
[ 1658.281442]  [<ffffffff81059226>] ? autoremove_wake_function+0x0/0x3d
[ 1658.281450]  [<ffffffff8106817c>] ? trace_hardirqs_on+0xd/0xf
[ 1658.281458]  [<ffffffff810540c3>] ? worker_thread+0x0/0x350
[ 1658.281465]  [<ffffffff81058e34>] kthread+0x94/0x9c
[ 1658.281473]  [<ffffffff8100c29a>] child_rip+0xa/0x20
[ 1658.281481]  [<ffffffff8100bc00>] ? restore_args+0x0/0x30
[ 1658.281488]  [<ffffffff81058da0>] ? kthread+0x0/0x9c
[ 1658.281495]  [<ffffffff8100c290>] ? child_rip+0x0/0x20
[ 1658.281499] ---[ end trace 644f4c2ff2fe5981 ]---

Re: WARNINGs in usb-serial.c

[Alan Stern]

On Fri, 4 Sep 2009, Miklos Szeredi wrote:

> On Thu, 3 Sep 2009, Greg KH wrote:
> > On Thu, Sep 03, 2009 at 04:13:34PM +0200, Miklos Szeredi wrote:
> > > I get the following warnings in 2.6.31-rc.  A lot of them:
> > > 
> > > WARNING: at drivers/usb/serial/usb-serial.c:414 serial_write_room+0x59/0x6e [usbserial]()
> > > WARNING: at drivers/usb/serial/usb-serial.c:401 serial_write+0x77/0x9d [usbserial]()
> > > 
> > > This is a huawei-3565 modem.
> > > 
> > > The messages don't seem to hurt, but there's lot of trouble with this
> > > gadget.  Sometimes it just doesn't work after a while and a reboot is
> > > needed.  Sometimes it hangs the kernel after suspend, etc.  Not sure
> > > if this is related to the warnings...
> > 
> > {sigh}
> > 
> > The tty layer changes are being a pain here :(
> > 
> > Alan Stern posted a set of patches to the linux-usb list to hopefully
> > address stuff like this, is there any way you could test them out to see
> > if they help or not?
> 
> Nope, it doesn't seem to help.  Still got the same warnings with the
> patched kernel (latest git + ghk tree + usbserial patches).

What were you doing when these warnings appeared?

Do you want to try some debugging?  Add a line saying

#define DEBUG

near the beginning of the usb-serial.c source file, before all the 
#include lines.

Alan Stern

Re: WARNINGs in usb-serial.c

[Alan Stern]

On Fri, 4 Sep 2009, Alan Cox wrote:

> On Fri, 4 Sep 2009 10:17:30 -0400 (EDT)
> Alan Stern <stern@rowland.harvard.edu> wrote:
> 
> > On Fri, 4 Sep 2009, Miklos Szeredi wrote:
> > 
> > > On Thu, 3 Sep 2009, Greg KH wrote:
> > > > On Thu, Sep 03, 2009 at 04:13:34PM +0200, Miklos Szeredi wrote:
> > > > > I get the following warnings in 2.6.31-rc.  A lot of them:
> > > > > 
> > > > > WARNING: at drivers/usb/serial/usb-serial.c:414
> > > > > serial_write_room+0x59/0x6e [usbserial]() WARNING: at
> > > > > drivers/usb/serial/usb-serial.c:401 serial_write+0x77/0x9d
> > > > > [usbserial]()
> > > > > 
> > > > > This is a huawei-3565 modem.
> > > > > 
> > > > > The messages don't seem to hurt, but there's lot of trouble
> > > > > with this gadget.  Sometimes it just doesn't work after a while
> > > > > and a reboot is needed.  Sometimes it hangs the kernel after
> > > > > suspend, etc.  Not sure if this is related to the warnings...
> > > > 
> > > > {sigh}
> > > > 
> > > > The tty layer changes are being a pain here :(
> > > > 
> > > > Alan Stern posted a set of patches to the linux-usb list to
> > > > hopefully address stuff like this, is there any way you could
> > > > test them out to see if they help or not?
> > > 
> > > Nope, it doesn't seem to help.  Still got the same warnings with the
> > > patched kernel (latest git + ghk tree + usbserial patches).
> > 
> > What were you doing when these warnings appeared?
> 
> The usual way to get it was
> 
> 	close
> 		users = 0
> 		ldisc processing
> 		echo
> 		write room
> 			hey we are closed
> 				Spew
> 
> I suspect the actual check in write_room is now simply bogus with it
> all being refcounted (the ldisc will hold a tty kref at that point)

That makes sense.  It would mean that all those

	WARN_ON(!port->port.count);

lines in usb-serial.c should simply be removed.  Miklos, do you want to 
try removing them?

Alan Stern

Re: WARNINGs in usb-serial.c

[Alan Cox]

> > Do you have a pointer to the patches, please?  I need it for the
> > regression list.

Not a regression alas.. always been buggy and the warnings go back
forever too

> They were posted on the linux-usb mailing list, I'm still fighting my
> patch queue to get them into my tree soon.

They fix the refcounting properly - I need to review them for Alan when
next week but they look robust. All the old uglies go away with the
move to full refcounting everywhere as the nasty cases when an ldisc
echoes chars into a port as it closed just come out in the refcounting.

Re: WARNINGs in usb-serial.c

[Alan Cox]

On Fri, 4 Sep 2009 10:17:30 -0400 (EDT)
Alan Stern <stern@rowland.harvard.edu> wrote:

> On Fri, 4 Sep 2009, Miklos Szeredi wrote:
> 
> > On Thu, 3 Sep 2009, Greg KH wrote:
> > > On Thu, Sep 03, 2009 at 04:13:34PM +0200, Miklos Szeredi wrote:
> > > > I get the following warnings in 2.6.31-rc.  A lot of them:
> > > > 
> > > > WARNING: at drivers/usb/serial/usb-serial.c:414
> > > > serial_write_room+0x59/0x6e [usbserial]() WARNING: at
> > > > drivers/usb/serial/usb-serial.c:401 serial_write+0x77/0x9d
> > > > [usbserial]()
> > > > 
> > > > This is a huawei-3565 modem.
> > > > 
> > > > The messages don't seem to hurt, but there's lot of trouble
> > > > with this gadget.  Sometimes it just doesn't work after a while
> > > > and a reboot is needed.  Sometimes it hangs the kernel after
> > > > suspend, etc.  Not sure if this is related to the warnings...
> > > 
> > > {sigh}
> > > 
> > > The tty layer changes are being a pain here :(
> > > 
> > > Alan Stern posted a set of patches to the linux-usb list to
> > > hopefully address stuff like this, is there any way you could
> > > test them out to see if they help or not?
> > 
> > Nope, it doesn't seem to help.  Still got the same warnings with the
> > patched kernel (latest git + ghk tree + usbserial patches).
> 
> What were you doing when these warnings appeared?

The usual way to get it was

	close
		users = 0
		ldisc processing
		echo
		write room
			hey we are closed
				Spew

I suspect the actual check in write_room is now simply bogus with it
all being refcounted (the ldisc will hold a tty kref at that point)

Re: WARNINGs in usb-serial.c

[Miklos Szeredi]

On Fri, 4 Sep 2009, Alan Stern wrote:
> On Fri, 4 Sep 2009, Alan Cox wrote:
> 
> > On Fri, 4 Sep 2009 10:17:30 -0400 (EDT)
> > Alan Stern <stern@rowland.harvard.edu> wrote:
> > 
> > > On Fri, 4 Sep 2009, Miklos Szeredi wrote:
> > > 
> > > > On Thu, 3 Sep 2009, Greg KH wrote:
> > > > > On Thu, Sep 03, 2009 at 04:13:34PM +0200, Miklos Szeredi wrote:
> > > > > > I get the following warnings in 2.6.31-rc.  A lot of them:
> > > > > > 
> > > > > > WARNING: at drivers/usb/serial/usb-serial.c:414
> > > > > > serial_write_room+0x59/0x6e [usbserial]() WARNING: at
> > > > > > drivers/usb/serial/usb-serial.c:401 serial_write+0x77/0x9d
> > > > > > [usbserial]()
> > > > > > 
> > > > > > This is a huawei-3565 modem.
> > > > > > 
> > > > > > The messages don't seem to hurt, but there's lot of trouble
> > > > > > with this gadget.  Sometimes it just doesn't work after a while
> > > > > > and a reboot is needed.  Sometimes it hangs the kernel after
> > > > > > suspend, etc.  Not sure if this is related to the warnings...
> > > > > 
> > > > > {sigh}
> > > > > 
> > > > > The tty layer changes are being a pain here :(
> > > > > 
> > > > > Alan Stern posted a set of patches to the linux-usb list to
> > > > > hopefully address stuff like this, is there any way you could
> > > > > test them out to see if they help or not?
> > > > 
> > > > Nope, it doesn't seem to help.  Still got the same warnings with the
> > > > patched kernel (latest git + ghk tree + usbserial patches).

Here's a reproducible Oops on that kernel when trying to connect with
wvdial.  This is a regression compared to -linus, where wvdial works
(most of the time anyway).

I can bisect it if it's not immediately obvious what is happening...

Thanks,
Miklos
---


BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
IP: [<ffffffffa020709c>] serial_chars_in_buffer+0x47/0x5f [usbserial]
PGD 0 
Oops: 0000 [#1] PREEMPT SMP 
last sysfs file: /sys/class/rfkill/rfkill2/state
CPU 0 
Modules linked in: ppp_generic slhc option usbserial nls_iso8859_1 nls_cp437 vfat fat usb_storage bnep rfcomm sco l2cap acpi_cpufreq nf_conntrack_netbios_ns microcode fuse iwl3945 iwlcore thinkpad_acpi mac80211 backlight btusb led_class bluetooth thermal ac battery processor button nsc_ircc irda crc_ccitt cfg80211 rfkill e1000e uinput [last unloaded: usbserial]
Pid: 5159, comm: pppd Tainted: G        W  2.6.31-rc8-gkh-00038-g37d0892-dirty #33 2007FUG
RIP: 0010:[<ffffffffa020709c>]  [<ffffffffa020709c>] serial_chars_in_buffer+0x47/0x5f [usbserial]
RSP: 0018:ffff8800ac753d78  EFLAGS: 00010246
RAX: 0000000000000000 RBX: ffff8800bf3d8800 RCX: 000000000000001a
RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff88001912a000
RBP: ffff8800ac753d88 R08: 00007f8611e2d1f0 R09: ffff8800ac753f28
R10: 3d4449505f445050 R11: 0000000000000246 R12: ffff88001912a000
R13: ffff88001912a000 R14: ffff88001912a000 R15: ffff88001912a000
FS:  00007f86105b96f0(0000) GS:ffff880001f3d000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000018 CR3: 000000008d7db000 CR4: 00000000000006f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process pppd (pid: 5159, threadinfo ffff8800ac752000, task ffff88001914e040)
Stack:
 ffff8800ac675c00 7fffffffffffffff ffff8800ac753d98 ffffffff811c271e
<0> ffff8800ac753e08 ffffffff811c2c73 ffff8800ac753df8 0000000000000046
<0> ffff88001914e040 ffffffff810c676a ffff8800ac675ac0 ffff8800bf840bc0
Call Trace:
 [<ffffffff811c271e>] tty_chars_in_buffer+0x1a/0x1c
 [<ffffffff811c2c73>] tty_wait_until_sent+0x32/0xfc
 [<ffffffff810c676a>] ? kmem_cache_free+0x118/0x18b
 [<ffffffff811be720>] tty_ioctl+0xa6/0x891
 [<ffffffff810d826e>] vfs_ioctl+0x2f/0x7d
 [<ffffffff810d87eb>] do_vfs_ioctl+0x4af/0x4ec
 [<ffffffff810cc1ae>] ? fget+0x0/0x127
 [<ffffffff8100b1cc>] ? sysret_check+0x27/0x62
 [<ffffffff810d886f>] sys_ioctl+0x47/0x6a
 [<ffffffff8100b19b>] system_call_fastpath+0x16/0x1b
Code: 00 74 23 0f b6 8b 50 02 00 00 48 c7 c2 20 ac 20 a0 48 c7 c6 67 b0 20 a0 48 c7 c7 87 b0 20 a0 31 c0 e8 13 53 11 e1 48 8b 13 31 c0 <f6> 42 18 01 75 0d 48 8b 42 08 4c 89 e7 ff 90 58 01 00 00 5b 41 
RIP  [<ffffffffa020709c>] serial_chars_in_buffer+0x47/0x5f [usbserial]
 RSP <ffff8800ac753d78>
CR2: 0000000000000018
---[ end trace 644f4c2ff2fe598a ]---

Re: WARNINGs in usb-serial.c

[Alan Stern]

On Mon, 7 Sep 2009, Miklos Szeredi wrote:

> Here's a reproducible Oops on that kernel when trying to connect with
> wvdial.  This is a regression compared to -linus, where wvdial works
> (most of the time anyway).
> 
> I can bisect it if it's not immediately obvious what is happening...

I don't think bisecting will help (or is even possible).

> BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
> IP: [<ffffffffa020709c>] serial_chars_in_buffer+0x47/0x5f [usbserial]

It's difficult to say without an assembly listing, but I gather that
serial_chars_in_buffer() is seeing port->serial == NULL.  Can you
verify this?

This is unexpected, because port->serial is initialized in
usb_serial_probe() and is not set to NULL until destroy_serial(), after
which port should not be used at all.  Can you add a

#define DEBUG

line at the start of usb-serial.c (before the #include lines) so that
we can tell if destroy_serial() is getting called too early?  When you
do, post the dmesg log showing everything from the time you start
running your test.

Alan Stern

Re: WARNINGs in usb-serial.c

[Miklos Szeredi]

On Mon, 7 Sep 2009, Alan Stern wrote:
> On Mon, 7 Sep 2009, Miklos Szeredi wrote:
> 
> > Here's a reproducible Oops on that kernel when trying to connect with
> > wvdial.  This is a regression compared to -linus, where wvdial works
> > (most of the time anyway).
> > 
> > I can bisect it if it's not immediately obvious what is happening...
> 
> I don't think bisecting will help (or is even possible).
> 
> > BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
> > IP: [<ffffffffa020709c>] serial_chars_in_buffer+0x47/0x5f [usbserial]
> 
> It's difficult to say without an assembly listing, but I gather that
> serial_chars_in_buffer() is seeing port->serial == NULL.  Can you
> verify this?

Yes, that is the case.

> This is unexpected, because port->serial is initialized in
> usb_serial_probe() and is not set to NULL until destroy_serial(), after
> which port should not be used at all.  Can you add a
> 
> #define DEBUG
> 
> line at the start of usb-serial.c (before the #include lines) so that
> we can tell if destroy_serial() is getting called too early?  When you
> do, post the dmesg log showing everything from the time you start
> running your test.

drivers/usb/serial/usb-serial.c: serial_install
drivers/usb/serial/usb-serial.c: serial_open - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x541e
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5402
drivers/usb/serial/usb-serial.c: serial_set_termios - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5402
drivers/usb/serial/usb-serial.c: serial_set_termios - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_tiocmget - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5402
drivers/usb/serial/usb-serial.c: serial_set_termios - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 5 byte(s)
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 4 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 13 byte(s)
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 28 byte(s)
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
PPP generic driver version 2.4.2
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_open - port 0
drivers/usb/serial/usb-serial.c: serial_tiocmset - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5404
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_set_termios - port 0
drivers/usb/serial/usb-serial.c: serial_open - port 0
drivers/usb/serial/usb-serial.c: destroy_serial - GSM modem (1-port)
drivers/usb/serial/usb-serial.c: return_serial
drivers/usb/serial/usb-serial.c: serial_close - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
IP: [<ffffffffa01ca09c>] serial_chars_in_buffer+0x47/0x5f [usbserial]
PGD 0 
Oops: 0000 [#1] PREEMPT SMP 
last sysfs file: /sys/class/rfkill/rfkill2/state
CPU 0 
Modules linked in: ppp_generic slhc usb_storage option usbserial bnep sco rfcomm l2cap acpi_cpufreq nf_conntrack_netbios_ns microcode fuse iwl3945 iwlcore mac80211 thinkpad_acpi backlight btusb ac led_class nsc_ircc bluetooth cfg80211 button battery processor thermal irda uinput rfkill e1000e crc_ccitt
Pid: 5139, comm: pppd Not tainted 2.6.31-rc8-gkh-00038-g37d0892-dirty #42 2007FUG
RIP: 0010:[<ffffffffa01ca09c>]  [<ffffffffa01ca09c>] serial_chars_in_buffer+0x47/0x5f [usbserial]
RSP: 0018:ffff88009cc17d78  EFLAGS: 00010246
RAX: 0000000000000000 RBX: ffff8800b5d7a800 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffff88009cc17ca7
RBP: ffff88009cc17d88 R08: 0000000000000082 R09: ffffffff8105d685
R10: 0000000000000082 R11: 0000000000018600 R12: ffff8800b64af000
R13: ffff8800b64af000 R14: ffff8800b64af000 R15: ffff8800b64af000
FS:  00007ff05244d6f0(0000) GS:ffff880001f45000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000018 CR3: 000000009cc95000 CR4: 00000000000006f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process pppd (pid: 5139, threadinfo ffff88009cc16000, task ffff8800a89f4040)
Stack:
 ffff8800a547c940 7fffffffffffffff ffff88009cc17d98 ffffffff811c7aa2
<0> ffff88009cc17e08 ffffffff811c7ff7 ffff88009cc17df8 0000000000000046
<0> ffff8800a89f4040 ffffffff810c9f8a ffff8800aa902200 ffff8800bf840bc0
Call Trace:
 [<ffffffff811c7aa2>] tty_chars_in_buffer+0x1a/0x1c
 [<ffffffff811c7ff7>] tty_wait_until_sent+0x32/0xfc
 [<ffffffff810c9f8a>] ? kmem_cache_free+0x118/0x18b
 [<ffffffff811c3aa4>] tty_ioctl+0xa6/0x891
 [<ffffffff810dba8e>] vfs_ioctl+0x2f/0x7d
 [<ffffffff810dc00b>] do_vfs_ioctl+0x4af/0x4ec
 [<ffffffff810cf9ce>] ? fget+0x0/0x127
 [<ffffffff8100b1cc>] ? sysret_check+0x27/0x62
 [<ffffffff810dc08f>] sys_ioctl+0x47/0x6a
 [<ffffffff8100b19b>] system_call_fastpath+0x16/0x1b
Code: 00 74 23 0f b6 8b 50 02 00 00 48 c7 c2 20 dc 1c a0 48 c7 c6 67 e0 1c a0 48 c7 c7 87 e0 1c a0 31 c0 e8 93 76 15 e1 48 8b 13 31 c0 <f6> 42 18 01 75 0d 48 8b 42 08 4c 89 e7 ff 90 58 01 00 00 5b 41 
RIP  [<ffffffffa01ca09c>] serial_chars_in_buffer+0x47/0x5f [usbserial]
 RSP <ffff88009cc17d78>
CR2: 0000000000000018
---[ end trace ef2106e42e2196ab ]---

Re: WARNINGs in usb-serial.c

[Alan Stern]

On Mon, 7 Sep 2009, Miklos Szeredi wrote:

> > This is unexpected, because port->serial is initialized in
> > usb_serial_probe() and is not set to NULL until destroy_serial(), after
> > which port should not be used at all.  Can you add a
> > 
> > #define DEBUG
> > 
> > line at the start of usb-serial.c (before the #include lines) so that
> > we can tell if destroy_serial() is getting called too early?  When you
> > do, post the dmesg log showing everything from the time you start
> > running your test.
> 
> drivers/usb/serial/usb-serial.c: serial_install
> drivers/usb/serial/usb-serial.c: serial_open - port 0
...
> PPP generic driver version 2.4.2
> drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
> drivers/usb/serial/usb-serial.c: serial_open - port 0
> drivers/usb/serial/usb-serial.c: serial_tiocmset - port 0
> drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
> drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5404
> drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
> drivers/usb/serial/usb-serial.c: serial_set_termios - port 0
> drivers/usb/serial/usb-serial.c: serial_open - port 0

This is the third open with no intervening closes.  At this point
port->port.count should be equal to 3 (it gets incremented in
serial_open() and decremented when serial_close() calls
tty_port_close_start()).

> drivers/usb/serial/usb-serial.c: destroy_serial - GSM modem (1-port)
> drivers/usb/serial/usb-serial.c: return_serial
> drivers/usb/serial/usb-serial.c: serial_close - port 0

I don't understand this.  How did we get to destroy_serial()?  It is
called from only one place: usb_serial_put().  That in turn is called
from only a few places, of which the most important are
serial_release() and usb_serial_disconnect().  But neither of them
shows up in the debugging log.

We need more debugging info.  You can try printing the value of 
port->port.count just before the end of serial_open() and at the start 
of serial_close().  You can also add a WARN() at the start of 
destroy_serial() so that the stack dump will show how we got there.

> drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
> BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
> IP: [<ffffffffa01ca09c>] serial_chars_in_buffer+0x47/0x5f [usbserial]

Now this is understandable.  Since destroy_serial() was called too 
soon, anything afterward will try to follow a NULL pointer.

Alan Stern

Re: WARNINGs in usb-serial.c

[Miklos Szeredi]

On Mon, 7 Sep 2009, Alan Stern wrote:
> I don't understand this.  How did we get to destroy_serial()?  It is
> called from only one place: usb_serial_put().  That in turn is called
> from only a few places, of which the most important are
> serial_release() and usb_serial_disconnect().  But neither of them
> shows up in the debugging log.
> 
> We need more debugging info.  You can try printing the value of 
> port->port.count just before the end of serial_open() and at the start 
> of serial_close().  You can also add a WARN() at the start of 
> destroy_serial() so that the stack dump will show how we got there.

OK, here's the debug output with the info.  Looks like the
destroy_serial() is called via serial_open().

drivers/usb/serial/usb-serial.c: serial_install
drivers/usb/serial/usb-serial.c: serial_open - port 0
serial_open = 1
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x541e
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5402
drivers/usb/serial/usb-serial.c: serial_set_termios - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5402
drivers/usb/serial/usb-serial.c: serial_set_termios - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_tiocmget - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5402
drivers/usb/serial/usb-serial.c: serial_set_termios - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 5 byte(s)
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 4 byte(s)
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 13 byte(s)
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
drivers/usb/serial/usb-serial.c: serial_write - port 0, 28 byte(s)
drivers/usb/serial/usb-serial.c: serial_write - port 0, 1 byte(s)
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: usb_serial_port_work - port 0
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_write_room - port 0
PPP generic driver version 2.4.2
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_open - port 0
serial_open = 2
drivers/usb/serial/usb-serial.c: serial_tiocmset - port 0
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5404
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
drivers/usb/serial/usb-serial.c: serial_set_termios - port 0
drivers/usb/serial/usb-serial.c: serial_open - port 0
Pid: 5007, comm: pppd Not tainted 2.6.31-rc8-gkh-00038-g37d0892-dirty #42
Call Trace:
 [<ffffffff810687bb>] ? trace_hardirqs_on_caller+0x10b/0x12f
 [<ffffffffa01cc532>] ? destroy_serial+0x0/0x10e [usbserial]
 [<ffffffffa01cc54a>] destroy_serial+0x18/0x10e [usbserial]
 [<ffffffffa01cc532>] ? destroy_serial+0x0/0x10e [usbserial]
 [<ffffffff8116ddbd>] kref_put+0x43/0x4f
 [<ffffffffa01cb0e3>] serial_open+0x11b/0x188 [usbserial]
 [<ffffffff811c4d6d>] tty_open+0x30a/0x431
 [<ffffffff810d1785>] chrdev_open+0x19c/0x1bb
 [<ffffffff81324e61>] ? _spin_unlock+0x2b/0x55
 [<ffffffff810cf63f>] ? file_move+0x23/0x55
 [<ffffffff810d15e9>] ? chrdev_open+0x0/0x1bb
 [<ffffffff810cd1ab>] __dentry_open+0x184/0x2a3
 [<ffffffff810cd3a1>] nameidata_to_filp+0x46/0x57
 [<ffffffff810da70f>] do_filp_open+0x4f3/0x9bd
 [<ffffffff810e3c3f>] ? alloc_fd+0x122/0x133
 [<ffffffff810ccf2d>] do_sys_open+0x62/0x110
 [<ffffffff810cd00e>] sys_open+0x20/0x22
 [<ffffffff8100b19b>] system_call_fastpath+0x16/0x1b
drivers/usb/serial/usb-serial.c: destroy_serial - GSM modem (1-port)
drivers/usb/serial/usb-serial.c: return_serial
serial_open = 3
drivers/usb/serial/usb-serial.c: serial_close - port 0
serial_close = 3
drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
IP: [<ffffffffa01ca09c>] serial_chars_in_buffer+0x47/0x5f [usbserial]
PGD 0 
Oops: 0000 [#1] PREEMPT SMP 
last sysfs file: /sys/class/rfkill/rfkill1/state
CPU 0 
Modules linked in: ppp_generic slhc usb_storage option usbserial bnep sco rfcomm l2cap acpi_cpufreq nf_conntrack_netbios_ns microcode fuse thinkpad_acpi iwl3945 backlight battery iwlcore led_class ac nsc_ircc mac80211 processor thermal button btusb bluetooth irda cfg80211 crc_ccitt rfkill e1000e uinput
Pid: 5007, comm: pppd Not tainted 2.6.31-rc8-gkh-00038-g37d0892-dirty #42 2007FUG
RIP: 0010:[<ffffffffa01ca09c>]  [<ffffffffa01ca09c>] serial_chars_in_buffer+0x47/0x5f [usbserial]
RSP: 0018:ffff88009a01fd78  EFLAGS: 00010246
RAX: 0000000000000000 RBX: ffff8800b2067000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffff88009a01fca7
RBP: ffff88009a01fd88 R08: 0000000000000082 R09: ffffffff8105d685
R10: 0000000000000082 R11: 0000000000018600 R12: ffff8800afa31000
R13: ffff8800afa31000 R14: ffff8800afa31000 R15: ffff8800afa31000
FS:  00007ff6efec46f0(0000) GS:ffff880001f45000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000018 CR3: 000000009e9e7000 CR4: 00000000000006f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process pppd (pid: 5007, threadinfo ffff88009a01e000, task ffff88009e878040)
Stack:
 ffff8800a715d840 7fffffffffffffff ffff88009a01fd98 ffffffff811c7aa2
<0> ffff88009a01fe08 ffffffff811c7ff7 ffff88009a01fdf8 0000000000000046
<0> ffff88009e878040 ffffffff810c9f8a ffff8800a715d200 ffff8800bf840bc0
Call Trace:
 [<ffffffff811c7aa2>] tty_chars_in_buffer+0x1a/0x1c
 [<ffffffff811c7ff7>] tty_wait_until_sent+0x32/0xfc
 [<ffffffff810c9f8a>] ? kmem_cache_free+0x118/0x18b
 [<ffffffff811c3aa4>] tty_ioctl+0xa6/0x891
 [<ffffffff810dba8e>] vfs_ioctl+0x2f/0x7d
 [<ffffffff810dc00b>] do_vfs_ioctl+0x4af/0x4ec
 [<ffffffff810cf9ce>] ? fget+0x0/0x127
 [<ffffffff8100b1cc>] ? sysret_check+0x27/0x62
 [<ffffffff810dc08f>] sys_ioctl+0x47/0x6a
 [<ffffffff8100b19b>] system_call_fastpath+0x16/0x1b
Code: 00 74 23 0f b6 8b 50 02 00 00 48 c7 c2 60 dc 1c a0 48 c7 c6 a7 e0 1c a0 48 c7 c7 c7 e0 1c a0 31 c0 e8 93 76 15 e1 48 8b 13 31 c0 <f6> 42 18 01 75 0d 48 8b 42 08 4c 89 e7 ff 90 58 01 00 00 5b 41 
RIP  [<ffffffffa01ca09c>] serial_chars_in_buffer+0x47/0x5f [usbserial]
 RSP <ffff88009a01fd78>
CR2: 0000000000000018
---[ end trace 6b3c350da83d5762 ]---

Re: WARNINGs in usb-serial.c

[Alan Stern]

On Mon, 7 Sep 2009, Miklos Szeredi wrote:

> OK, here's the debug output with the info.  Looks like the
> destroy_serial() is called via serial_open().
> 
> drivers/usb/serial/usb-serial.c: serial_install
> drivers/usb/serial/usb-serial.c: serial_open - port 0
> serial_open = 1
...
> drivers/usb/serial/usb-serial.c: serial_open - port 0
> serial_open = 2
> drivers/usb/serial/usb-serial.c: serial_tiocmset - port 0
> drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5401
> drivers/usb/serial/usb-serial.c: serial_ioctl - port 0, cmd 0x5404
> drivers/usb/serial/usb-serial.c: serial_chars_in_buffer = port 0
> drivers/usb/serial/usb-serial.c: serial_set_termios - port 0
> drivers/usb/serial/usb-serial.c: serial_open - port 0
> Pid: 5007, comm: pppd Not tainted 2.6.31-rc8-gkh-00038-g37d0892-dirty #42
> Call Trace:
>  [<ffffffff810687bb>] ? trace_hardirqs_on_caller+0x10b/0x12f
>  [<ffffffffa01cc532>] ? destroy_serial+0x0/0x10e [usbserial]
>  [<ffffffffa01cc54a>] destroy_serial+0x18/0x10e [usbserial]
>  [<ffffffffa01cc532>] ? destroy_serial+0x0/0x10e [usbserial]
>  [<ffffffff8116ddbd>] kref_put+0x43/0x4f
>  [<ffffffffa01cb0e3>] serial_open+0x11b/0x188 [usbserial]

You're right; serial_open() is somehow calling usb_serial_put().

But in my version of the code there's no way for that to happen.  Could 
it be that your version is different from mine?  For comparison, here 
is my copy of serial_open().

Alan Stern


static int serial_open(struct tty_struct *tty, struct file *filp)
{
	struct usb_serial_port *port = tty->driver_data;
	struct usb_serial *serial = port->serial;
	int retval;

	dbg("%s - port %d", __func__, port->number);

	spin_lock_irq(&port->port.lock);
	if (!tty_hung_up_p(filp))
		++port->port.count;
	spin_unlock_irq(&port->port.lock);
	tty_port_tty_set(&port->port, tty);

	/* Do the device-specific open only if the hardware isn't
	 * already initialized.
	 */
	if (!test_bit(ASYNCB_INITIALIZED, &port->port.flags)) {
		if (mutex_lock_interruptible(&port->mutex))
			return -ERESTARTSYS;
		mutex_lock(&serial->disc_mutex);
		if (serial->disconnected)
			retval = -ENODEV;
		else
			retval = port->serial->type->open(tty, port);
		mutex_unlock(&serial->disc_mutex);
		mutex_unlock(&port->mutex);
		if (retval)
			return retval;
		set_bit(ASYNCB_INITIALIZED, &port->port.flags);
	}

	/* Now do the correct tty layer semantics */
	retval = tty_port_block_til_ready(&port->port, tty, filp);
	return retval;
}

Re: WARNINGs in usb-serial.c

[Miklos Szeredi]

On Mon, 7 Sep 2009, Alan Stern wrote:
> 
> You're right; serial_open() is somehow calling usb_serial_put().
> 
> But in my version of the code there's no way for that to happen.  Could 
> it be that your version is different from mine?  For comparison, here 
> is my copy of serial_open().

Argh... I didn't apply 8/8 of your series.

Now everything seems to be working fine (I still get the WARNING's but
that appears to be normal).  Sorry for the noise.

Thanks,
Miklos