2.6.27-rc5-mmotm0829 - CONFIG_HID_COMPAT causes hangs at boot

2.6.27-rc5-mmotm0829 - CONFIG_HID_COMPAT causes hangs at boot

[Valdis.Kletnieks]

[-- Attachment #1: Type: text/plain, Size: 1697 bytes --]

I built a rc5-mmotm kernel, and set CONFIG_HID_COMPAT=y, but then found
that I didn't actually *need* any of quirks files that tries to load, so
those all got set to 'n'.

The resulting kernel would get this far (using a HID_COMPAT=n kernel's dmesg
and annotating, I couldn't get netconsole) and then hang while still running
off the initrd:

[    1.665167] usb 1-8: New USB device found, idVendor=413c, idProduct=0058
[    1.678083] usb 1-8: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.753101] usb 1-8.1: new low speed USB device using ehci_hcd and address 5
[    1.842008] usb 1-8.1: configuration #1 chosen from 1 choice
[    1.869343] usb 1-8.1: New USB device found, idVendor=045e, idProduct=0023
[    1.882267] usb 1-8.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    1.895189] usb 1-8.1: Product: Microsoft Trackball Optical®
[    1.908056] usb 1-8.1: Manufacturer: Microsoft

(the next line would make it to the console)

[    1.926685] input: Microsoft Microsoft Trackball Optical® as /devices/pci000:00/0000:00:1d.7/usb1/1-8/1-8.1/1-8.1:1.0/input/input1
[    1.945217] generic-usb 0003:045E:0023.0001: input,hidraw0: USB HID v1.00 Mouse [Microsoft Microsoft Trackball Optical®] on usb-0000:00:1d.7-8.1/input0
[    1.959193] usbcore: registered new interface driver usbhid
[    1.973037] usbhid: v2.6:USB HID core driver

(the following line would not)
[    1.987014] Advanced Linux Sound Architecture Driver Version 1.0.18rc1.

Poking around with sysrq-T would show a modprobe process running and not
making any progress, just hung waiting for something.  I can go get the
traceback if needed.

This ring any bells?

[-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --]

Re: 2.6.27-rc5-mmotm0829 - CONFIG_HID_COMPAT causes hangs at boot

[Jiri Slaby]

Valdis.Kletnieks@vt.edu napsal(a):
> I built a rc5-mmotm kernel, and set CONFIG_HID_COMPAT=y, but then found
> that I didn't actually *need* any of quirks files that tries to load, so
> those all got set to 'n'.
> 
> The resulting kernel would get this far (using a HID_COMPAT=n kernel's dmesg
> and annotating, I couldn't get netconsole) and then hang while still running
> off the initrd:
> 
> [    1.665167] usb 1-8: New USB device found, idVendor=413c, idProduct=0058
> [    1.678083] usb 1-8: New USB device strings: Mfr=0, Product=0, SerialNumber=0
> [    1.753101] usb 1-8.1: new low speed USB device using ehci_hcd and address 5
> [    1.842008] usb 1-8.1: configuration #1 chosen from 1 choice
> [    1.869343] usb 1-8.1: New USB device found, idVendor=045e, idProduct=0023
> [    1.882267] usb 1-8.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
> [    1.895189] usb 1-8.1: Product: Microsoft Trackball Optical®
> [    1.908056] usb 1-8.1: Manufacturer: Microsoft
> 
> (the next line would make it to the console)
> 
> [    1.926685] input: Microsoft Microsoft Trackball Optical® as /devices/pci000:00/0000:00:1d.7/usb1/1-8/1-8.1/1-8.1:1.0/input/input1
> [    1.945217] generic-usb 0003:045E:0023.0001: input,hidraw0: USB HID v1.00 Mouse [Microsoft Microsoft Trackball Optical®] on usb-0000:00:1d.7-8.1/input0
> [    1.959193] usbcore: registered new interface driver usbhid
> [    1.973037] usbhid: v2.6:USB HID core driver
> 
> (the following line would not)
> [    1.987014] Advanced Linux Sound Architecture Driver Version 1.0.18rc1.
> 
> Poking around with sysrq-T would show a modprobe process running and not
> making any progress, just hung waiting for something.  I can go get the
> traceback if needed.

I'm confused of your description. Which line exactly is the last one on
HID_COMPAT=y and which lines go through with n -- does it hang too?

> This ring any bells?

Not really, sorry.

Re: 2.6.27-rc5-mmotm0829 - CONFIG_HID_COMPAT causes hangs at boot

[Valdis.Kletnieks]

[-- Attachment #1: Type: text/plain, Size: 1834 bytes --]

On Tue, 02 Sep 2008 16:26:40 +0200, Jiri Slaby said:

OK, I'll annotate line-by-line.  This is a console from a boot of a kernel
built with HID_COMPAT=n (which works just fine).  I couldn't get a netconsole
of a COMPAT=y boot for other reasons, and it doesn't live long enough to get a
dmesg.

Both kernels are OK here.
> > [    1.665167] usb 1-8: New USB device found, idVendor=413c, idProduct=0058
> > [    1.678083] usb 1-8: New USB device strings: Mfr=0, Product=0, SerialNumber=0
> > [    1.753101] usb 1-8.1: new low speed USB device using ehci_hcd and address 5
> > [    1.842008] usb 1-8.1: configuration #1 chosen from 1 choice
> > [    1.869343] usb 1-8.1: New USB device found, idVendor=045e, idProduct=0023
> > [    1.882267] usb 1-8.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
> > [    1.895189] usb 1-8.1: Product: Microsoft Trackball Optical®
> > [    1.908056] usb 1-8.1: Manufacturer: Microsoft

The next line would make it to the console in both cases.
> > [    1.926685] input: Microsoft Microsoft Trackball Optical® as /devices/pci000:00/0000:00:1d.7/usb1/1-8/1-8.1/1-8.1:1.0/input/input1

The following 3 lines don't go to console by default due to loglevel setting.
So I'm not sure exactly where it hangs. But it's somewhere in here.
> > [    1.945217] generic-usb 0003:045E:0023.0001: input,hidraw0: USB HID v1.00 Mouse [Microsoft Microsoft Trackball Optical®] on usb-0000:00:1d.7-8.1/input0
> > [    1.959193] usbcore: registered new interface driver usbhid
> > [    1.973037] usbhid: v2.6:USB HID core driver

This line *should* make it to the console, but doesn't. So the failure is
before this point.
> > [    1.987014] Advanced Linux Sound Architecture Driver Version 1.0.18rc1.

I'll go back and instrument it more heavily so there's more info available.

[-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --]

Re: 2.6.27-rc5-mmotm0829 - CONFIG_HID_COMPAT causes hangs at boot

[Jiri Slaby]

On 09/02/2008 06:11 PM, Valdis.Kletnieks@vt.edu wrote:
> The following 3 lines don't go to console by default due to loglevel setting.
> So I'm not sure exactly where it hangs. But it's somewhere in here.

You may use `ignore_loglevel', `debug' or `loglevel=7' kernel parameter.

>>> [    1.945217] generic-usb 0003:045E:0023.0001: input,hidraw0: USB HID v1.00 Mouse [Microsoft Microsoft Trackball Optical®] on usb-0000:00:1d.7-8.1/input0
>>> [    1.959193] usbcore: registered new interface driver usbhid
>>> [    1.973037] usbhid: v2.6:USB HID core driver
> 
> This line *should* make it to the console, but doesn't. So the failure is
> before this point.
>>> [    1.987014] Advanced Linux Sound Architecture Driver Version 1.0.18rc1.
> 
> I'll go back and instrument it more heavily so there's more info available.

Ok, thanks.

Re: 2.6.27-rc5-mmotm0829 - CONFIG_HID_COMPAT causes hangs at boot

[Valdis.Kletnieks]

[-- Attachment #1: Type: text/plain, Size: 2752 bytes --]

(Adding Alan Cox to the cc: in case he can shed light on this one - it
appears that HID_COMPAT only puts the bullet in the chamber, and doesn't
actually cause the hang...)

On Tue, 02 Sep 2008 23:02:42 +0200, Jiri Slaby said:
> On 09/02/2008 06:11 PM, Valdis.Kletnieks@vt.edu wrote:
> > The following 3 lines don't go to console by default due to loglevel setting.
> > So I'm not sure exactly where it hangs. But it's somewhere in here.

Right around here, we kick off a modprobe for 'hid_dummy'.
> >>> [    1.959193] usbcore: registered new interface driver usbhid
> >>> [    1.973037] usbhid: v2.6:USB HID core driver

And since my initrd doesn't include any modules (since until now, I've had
a kernel that can everything builtin so it can boot far enough to do the
whole udev/modprobe off my root filesystem, and hid_dummy is a new one on
me), this modprobe spits out a:

modprobe: FATAL: Could not open '/lib/modules/2.6.27-rc5-mmotm0829/modules.dep': No such file or directory

Well, yeah.. No modules on the initrd, so no modules.dep.  But having spewed
its error message, modprobe apparently decides to go off in a snit and hang.
Eventually, the usermode_helper call does a wait() on the modprobe, and then
*that* hangs because modprobe isn't returning.  And eventually the whole
level of initcalls comes to a screeching halt...

And here's the totally unexpected kernel traceback for the modprobe:

schedule_timeout+0x22/0xb4
? _raw_spin_lock+0xce/0x186
? _raw_spin_unlock+0xb7/0xe0
wait_for_common+-xb2/0xfb
? default_wake_function+0x0/0xf
wait_for_completion+0x18/0x1a
flush_cpu_workqueue+0x6b/0x77
? wq_barrior_func+0x0/0xf
flush_workqueue+0x4f/0x68
flush_scheduled_work+0x10/0x12
tty_ldisc_release+0x4a/0x21e
? _raw_pin_lock+0xce/0x186
? debug_mutex_unlock+0x127/0x14d
? mutex_unlock_slowpath+0x14a/0x15c
tty_release_dev+0x4da/0x508
? get_parent_ip+0x11/0x41
? get_parent_ip+0x11/0x41
tty_release+0x19/0x24
__fput+0xd9/0x198
fput+0x15/0x17
filp_close+0x67/0x72
sys_close+0xa9/0x104
system_call_fastpath+0x16/0x1b

WTF? We hang trying to close a tty??!?

So HID_COMPAT is basically off the hook here - it did the 'modprobe hid-dummy'
which *should* have just caused modprobe to print a nasty message and we
keep going... The *real* problem is that the modprobe then wedged up trying
to close the file descriptor after printing the nasty message...

Odd thought - is this modprobe popping before we've managed to fully set
up userspace I/O to the console?  It certainly *seems* to be firing before
the nash init script on the initrd starts running (the script starts off:

#!/bin/nash
mount -t proc /proc /proc
setquiet
echo Mounting proc filesystem

And we never see that 'echo'. So the modprobe is happening in *really* early
userspace...

[-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --]

Re: 2.6.27-rc5-mmotm0829 - CONFIG_HID_COMPAT causes hangs at boot

[Jiri Slaby]

Valdis.Kletnieks@vt.edu napsal(a):
> (Adding Alan Cox to the cc: in case he can shed light on this one - it
> appears that HID_COMPAT only puts the bullet in the chamber, and doesn't
> actually cause the hang...)
> 
> On Tue, 02 Sep 2008 23:02:42 +0200, Jiri Slaby said:
>> On 09/02/2008 06:11 PM, Valdis.Kletnieks@vt.edu wrote:
>>> The following 3 lines don't go to console by default due to loglevel setting.
>>> So I'm not sure exactly where it hangs. But it's somewhere in here.
> 
> Right around here, we kick off a modprobe for 'hid_dummy'.
>>>>> [    1.959193] usbcore: registered new interface driver usbhid
>>>>> [    1.973037] usbhid: v2.6:USB HID core driver
> 
> And since my initrd doesn't include any modules (since until now, I've had
> a kernel that can everything builtin so it can boot far enough to do the
> whole udev/modprobe off my root filesystem, and hid_dummy is a new one on
> me), this modprobe spits out a:
> 
> modprobe: FATAL: Could not open '/lib/modules/2.6.27-rc5-mmotm0829/modules.dep': No such file or directory
> 
> Well, yeah.. No modules on the initrd, so no modules.dep.  But having spewed
> its error message, modprobe apparently decides to go off in a snit and hang.
> Eventually, the usermode_helper call does a wait() on the modprobe, and then
> *that* hangs because modprobe isn't returning.  And eventually the whole
> level of initcalls comes to a screeching halt...
> 
> And here's the totally unexpected kernel traceback for the modprobe:
> 
> schedule_timeout+0x22/0xb4
> ? _raw_spin_lock+0xce/0x186
> ? _raw_spin_unlock+0xb7/0xe0
> wait_for_common+-xb2/0xfb
> ? default_wake_function+0x0/0xf
> wait_for_completion+0x18/0x1a
> flush_cpu_workqueue+0x6b/0x77
> ? wq_barrior_func+0x0/0xf
> flush_workqueue+0x4f/0x68
> flush_scheduled_work+0x10/0x12
> tty_ldisc_release+0x4a/0x21e
> ? _raw_pin_lock+0xce/0x186
> ? debug_mutex_unlock+0x127/0x14d
> ? mutex_unlock_slowpath+0x14a/0x15c
> tty_release_dev+0x4da/0x508
> ? get_parent_ip+0x11/0x41
> ? get_parent_ip+0x11/0x41
> tty_release+0x19/0x24
> __fput+0xd9/0x198
> fput+0x15/0x17
> filp_close+0x67/0x72
> sys_close+0xa9/0x104
> system_call_fastpath+0x16/0x1b
> 
> WTF? We hang trying to close a tty??!?

Hmm, *if* we stuck in request_module in hid, workqueue cannot be flushed and
tty waits... Could you stick 2 printks into hid_compat_load if it finishes?

Re: 2.6.27-rc5-mmotm0829 - CONFIG_HID_COMPAT causes hangs at boot

[Valdis.Kletnieks]

[-- Attachment #1: Type: text/plain, Size: 492 bytes --]

On Thu, 04 Sep 2008 16:55:23 +0200, Jiri Slaby said:

> Hmm, *if* we stuck in request_module in hid, workqueue cannot be flushed and
> tty waits... Could you stick 2 printks into hid_compat_load if it finishes?

I severely doubt that it's going to finish, as it stayed stuck at that same
point for at least 10-15 minutes or so - it took a while for alt-sysrq-t to get
down to the tracemod because I booted with 'boot_delay=100', and then the
time to find paper and pen, write it down, etc..


[-- Attachment #2: Type: application/pgp-signature, Size: 226 bytes --]