#2 devclass_register() fails when built-in to kernel

[Greg Haskins]

On Wed, Oct 14, 2009 at 01:05:30PM -0700, Ira W. Snyder wrote:
> On Tue, Oct 13, 2009 at 03:10:15PM -0700, Ira W. Snyder wrote:
> > On Tue, Oct 13, 2009 at 05:40:38PM -0400, Gregory Haskins wrote:
> > > Did you get that connector example I sent? Let me know if you have any
> > > questions or need further assistance.
> > >

Whoops, here's another bug or two. I think that the vbus_root.lock mutex
isn't being initialized before use by the vbus_devclass_register()
function.

This is probably because I built a kernel without modules. I compiled
everything into the kernel.

Here is the relevant portion of the kernel log. See further below for
more.

[ 0.008005] CPU: L2 cache: 2048K
[ 0.008542] mce: CPU supports 32 MCE banks
[ 0.009407] CPU: Intel QEMU Virtual CPU version 0.10.50 stepping 03
[ 0.010537] Checking 'hlt' instruction... OK.
[ 0.132990] NET: Registered protocol family 16
[ 0.134464] PCI: PCI BIOS revision 2.10 entry at 0xfb3c0, last bus=0
[ 0.135502] PCI: Using configuration type 1 for base access
[ 0.139155] bio: create slab <bio-0> at 0
[ 0.140327] ACPI: Interpreter disabled.
[ 0.141288] PCI: Probing PCI hardware
[ 0.141925] PCI: Probing PCI hardware (bus 00)
[ 0.143439] pci 0000:00:01.1: reg 20 io port: [0xc000-0xc00f]
[ 0.145687] pci 0000:00:02.0: reg 10 32bit mmio: [0xf0000000-0xf1ffffff]
[ 0.147303] pci 0000:00:02.0: reg 14 32bit mmio: [0xf2000000-0xf2000fff]
[ 0.150055] pci 0000:00:03.0: reg 10 32bit mmio: [0xf2020000-0xf203ffff]
[ 0.152052] pci 0000:00:03.0: reg 14 io port: [0xc040-0xc07f]
[ 0.153290] pci 0000:00:04.0: reg 10 io port: [0xc080-0xc09f]
[ 0.155442] pci 0000:00:01.0: PIIX/ICH IRQ router [8086:7000]
[ 0.156787] pnp: PnP ACPI: disabled
[ 0.157999] pci_bus 0000:00: resource 0 io: [0x00-0xffff]
[ 0.158909] pci_bus 0000:00: resource 1 mem: [0x000000-0xffffffff]
[ 0.160049] NET: Registered protocol family 2
[ 0.160852] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 0.162359] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[ 0.164739] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes)
[ 0.171413] TCP: Hash tables configured (established 131072 bind 65536)
[ 0.172515] TCP reno registered
[ 0.173157] NET: Registered protocol family 1
[ 0.173997] Unpacking initramfs...
[ 0.191661] Freeing initrd memory: 743k freed
[ 0.192796] platform rtc_cmos: registered platform RTC device (no PNP device found)
[ 0.194842] microcode: CPU0 sig=0x623, pf=0x0, revision=0x0
[ 0.195887] Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
[ 0.197156] Scanning for low memory corruption every 60 seconds
[ 0.198488] ------------[ cut here ]------------
[ 0.199295] WARNING: at kernel/mutex.c:207 mutex_lock_nested+0xba/0x21d()
[ 0.199780] Hardware name:
[ 0.199780] Modules linked in:
[ 0.199780] Pid: 1, comm: swapper Not tainted 2.6.31-01218-ge94d34e-dirty #2
[ 0.199780] Call Trace:
[ 0.199780] [<c101cd11>] warn_slowpath_common+0x60/0x77
[ 0.199780] [<c101cd35>] warn_slowpath_null+0xd/0x10
[ 0.199780] [<c11f3a95>] mutex_lock_nested+0xba/0x21d
[ 0.199780] [<c13145c1>] ? venettap_init+0x0/0xf
[ 0.199780] [<c1044c8a>] vbus_devclass_register+0x14/0x68
[ 0.199780] [<c13145c1>] ? venettap_init+0x0/0xf
[ 0.199780] [<c13145ce>] venettap_init+0xd/0xf
[ 0.199780] [<c100104b>] _stext+0x4b/0x135
[ 0.199780] [<c130543f>] kernel_init+0x7f/0xcd
[ 0.199780] [<c13053c0>] ? kernel_init+0x0/0xcd
[ 0.199780] [<c10030b3>] kernel_thread_helper+0x7/0x10
[ 0.199780] ---[ end trace 6d450e935ee1897c ]---
[ 0.199780] BUG: unable to handle kernel NULL pointer dereference at (null)
[ 0.199780] IP: [<c11f3abc>] mutex_lock_nested+0xe1/0x21d
[ 0.199780] *pde = 00000000
[ 0.199780] Oops: 0002 [#1]
[ 0.199780] last sysfs file:
[ 0.199780] Modules linked in:
[ 0.199780]
[ 0.199780] Pid: 1, comm: swapper Tainted: G W (2.6.31-01218-ge94d34e-dirty #2)
[ 0.199780] EIP: 0060:[<c11f3abc>] EFLAGS: 00010096 CPU: 0
[ 0.199780] EIP is at mutex_lock_nested+0xe1/0x21d
[ 0.199780] EAX: c182cf34 EBX: f780ef84 ECX: f780e000 EDX: 00000000
[ 0.199780] ESI: c182cf14 EDI: 00000246 EBP: f780efa0 ESP: f780ef7c
[ 0.199780] DS: 007b ES: 007b FS: 0000 GS: 00e0 SS: 0068
[ 0.199780] Process swapper (pid: 1, ti=f780e000 task=f7830000 task.ti=f780e000)
[ 0.199780] Stack:
[ 0.199780] c182cf18 f7830000 c182cf34 f780ef84 11111111 f780ef84 c133f714 c12ea490
[ 0.199780] <0> c13145c1 f780efb4 c1044c8a c133f714 00000000 c13145c1 f780efbc c13145ce
[ 0.199780] <0> f780efd4 c100104b 00000000 c133f714 00000000 00000000 f780efe0 c130543f
[ 0.199780] Call Trace:
[ 0.199780] [<c13145c1>] ? venettap_init+0x0/0xf
[ 0.199780] [<c1044c8a>] ? vbus_devclass_register+0x14/0x68
[ 0.199780] [<c13145c1>] ? venettap_init+0x0/0xf
[ 0.199780] [<c13145ce>] ? venettap_init+0xd/0xf
[ 0.199780] [<c100104b>] ? _stext+0x4b/0x135
[ 0.199780] [<c130543f>] ? kernel_init+0x7f/0xcd
[ 0.199780] [<c13053c0>] ? kernel_init+0x0/0xcd
[ 0.199780] [<c10030b3>] ? kernel_thread_helper+0x7/0x10
[ 0.199780] Code: 93 92 e2 ff 8d 5d e4 89 f0 89 da e8 75 20 e4 ff 8b 45 e0 89 da 8b 48 04 89 f0 e8 70 1e e4 ff 8b 56 24 8d 46 20 89 45 e4 89 5e 24 <89> 1a 8b 45 e0 89 55 e8 89 45 ec 83 c8 ff 87 06 48 0f 84 ca 00
[ 0.199780] EIP: [<c11f3abc>] mutex_lock_nested+0xe1/0x21d SS:ESP 0068:f780ef7c
[ 0.199780] CR2: 0000000000000000
[ 0.199780] ---[ end trace 6d450e935ee1897d ]---
[ 0.242852] Kernel panic - not syncing: Attempted to kill init!
[ 0.243838] Pid: 1, comm: swapper Tainted: G D W 2.6.31-01218-ge94d34e-dirty #2
[ 0.245108] Call Trace:
[ 0.245494] [<c101cdac>] panic+0x3f/0xd7
[ 0.246152] [<c101f1de>] do_exit+0x54/0x573
[ 0.246851] [<c101cb86>] ? print_oops_end_marker+0x1e/0x23
[ 0.247799] [<c10050ab>] oops_end+0x79/0x80
[ 0.248489] [<c1014c64>] no_context+0x10b/0x115
[ 0.249253] [<c1014df7>] __bad_area_nosemaphore+0xe8/0xf0
[ 0.250173] [<c1014e62>] bad_area_nosemaphore+0xd/0x10
[ 0.251043] [<c1014fda>] do_page_fault+0xec/0x208
[ 0.251836] [<c1014eee>] ? do_page_fault+0x0/0x208
[ 0.252657] [<c11f5138>] error_code+0x70/0x78
[ 0.253404] [<c11f3abc>] ? mutex_lock_nested+0xe1/0x21d
[ 0.254269] [<c13145c1>] ? venettap_init+0x0/0xf
[ 0.255033] [<c1044c8a>] vbus_devclass_register+0x14/0x68
[ 0.255981] [<c13145c1>] ? venettap_init+0x0/0xf
[ 0.256757] [<c13145ce>] venettap_init+0xd/0xf
[ 0.257504] [<c100104b>] _stext+0x4b/0x135
[ 0.258207] [<c130543f>] kernel_init+0x7f/0xcd
[ 0.258973] [<c13053c0>] ? kernel_init+0x0/0xcd
[ 0.259754] [<c10030b3>] kernel_thread_helper+0x7/0x10

Ok, so I hunted down where the mutex is initialized, and changed the
late_initcall() to subsys_initcall(), hoping to fix the problem. No
luck, I get a different error:

[ 0.004000] memory used by lock dependency info: 3487 kB
[ 0.004000] per task-struct memory footprint: 1152 bytes
[ 0.004022] Calibrating delay loop (skipped), value calculated using timer frequency.. 5667.00 BogoMIPS (lpj=11334000)
[ 0.005599] Mount-cache hash table entries: 512
[ 0.007012] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 0.007776] CPU: L2 cache: 2048K
[ 0.008028] mce: CPU supports 32 MCE banks
[ 0.008867] CPU: Intel QEMU Virtual CPU version 0.10.50 stepping 03
[ 0.009905] Checking 'hlt' instruction... OK.
[ 0.132981] NET: Registered protocol family 16
[ 0.134448] PCI: PCI BIOS revision 2.10 entry at 0xfb3c0, last bus=0
[ 0.135470] PCI: Using configuration type 1 for base access
[ 0.139059] BUG: unable to handle kernel NULL pointer dereference at (null)
[ 0.140001] IP: [<c1068ed8>] sget+0xcf/0x333
[ 0.140001] *pde = 00000000
[ 0.140001] Oops: 0000 [#1]
[ 0.140001] last sysfs file:
[ 0.140001] Modules linked in:
[ 0.140001]
[ 0.140001] Pid: 1, comm: swapper Not tainted (2.6.31-01218-ge94d34e-dirty #3)
[ 0.140001] EIP: 0060:[<c1068ed8>] EFLAGS: 00010287 CPU: 0
[ 0.140001] EIP is at sget+0xcf/0x333
[ 0.140001] EAX: f7830000 EBX: ffffff00 ECX: f78303b4 EDX: 00000001
[ 0.140001] ESI: 00000000 EDI: c12ec3a4 EBP: f780ef10 ESP: f780eef4
[ 0.140001] DS: 007b ES: 007b FS: 0000 GS: 00e0 SS: 0068
[ 0.140001] Process swapper (pid: 1, ti=f780e000 task=f7830000 task.ti=f780e000)
[ 0.140001] Stack:
[ 0.140001] c12ec3cc c12ec3bc c10689d6 c10689cc f78b7c80 c12ec3a4 00000000 f780ef2c
[ 0.007776] CPU: L2 cache: 2048K
[ 0.008028] mce: CPU supports 32 MCE banks
[ 0.008867] CPU: Intel QEMU Virtual CPU version 0.10.50 stepping 03
[ 0.009905] Checking 'hlt' instruction... OK.
[ 0.132981] NET: Registered protocol family 16
[ 0.134448] PCI: PCI BIOS revision 2.10 entry at 0xfb3c0, last bus=0
[ 0.135470] PCI: Using configuration type 1 for base access
[ 0.139059] BUG: unable to handle kernel NULL pointer dereference at (null)
[ 0.140001] IP: [<c1068ed8>] sget+0xcf/0x333
[ 0.140001] *pde = 00000000
[ 0.140001] Oops: 0000 [#1]
[ 0.140001] last sysfs file:
[ 0.140001] Modules linked in:
[ 0.140001]
[ 0.140001] Pid: 1, comm: swapper Not tainted (2.6.31-01218-ge94d34e-dirty #3)
[ 0.140001] EIP: 0060:[<c1068ed8>] EFLAGS: 00010287 CPU: 0
[ 0.140001] EIP is at sget+0xcf/0x333
[ 0.140001] EAX: f7830000 EBX: ffffff00 ECX: f78303b4 EDX: 00000001
[ 0.140001] ESI: 00000000 EDI: c12ec3a4 EBP: f780ef10 ESP: f780eef4
[ 0.140001] DS: 007b ES: 007b FS: 0000 GS: 00e0 SS: 0068
[ 0.140001] Process swapper (pid: 1, ti=f780e000 task=f7830000 task.ti=f780e000)
[ 0.140001] Stack:
[ 0.140001] c12ec3cc c12ec3bc c10689d6 c10689cc f78b7c80 c12ec3a4 00000000 f780ef2c
[ 0.140001] <0> c1069809 00000000 00000000 f78b7c80 c12ec3a4 fffffff4 f780ef3c c10a17db
[ 0.140001] <0> c10a17dd f78b7c80 f780ef60 c1069333 00000000 f78b7c80 c128b0d4 00000000
[ 0.140001] Call Trace:
[ 0.140001] [<c10689d6>] ? set_anon_super+0x0/0xc8
[ 0.140001] [<c10689cc>] ? compare_single+0x0/0xa
[ 0.140001] [<c1069809>] ? get_sb_single+0x1f/0x82
[ 0.140001] [<c10a17db>] ? configfs_get_sb+0x13/0x15
[ 0.140001] [<c10a17dd>] ? configfs_fill_super+0x0/0x9d
[ 0.140001] [<c1069333>] ? vfs_kern_mount+0x3b/0x76
[ 0.140001] [<c107cd8c>] ? simple_pin_fs+0x38/0x8c
[ 0.140001] [<c10a18a5>] ? configfs_pin_fs+0x17/0x1a
[ 0.140001] [<c10a0779>] ? configfs_register_subsystem+0x10/0x122
[ 0.140001] [<c10a1a1d>] ? config_group_init_type_name+0x1a/0x23
[ 0.140001] [<c1314435>] ? vbus_init+0x0/0xa9
[ 0.140001] [<c1314597>] ? vbus_config_init+0x86/0xb0
[ 0.140001] [<c1314451>] ? vbus_init+0x1c/0xa9
[ 0.140001] [<c100104b>] ? _stext+0x4b/0x135
[ 0.140001] [<c130543f>] ? kernel_init+0x7f/0xcd
[ 0.140001] [<c13053c0>] ? kernel_init+0x0/0xcd
[ 0.140001] [<c10030b3>] ? kernel_thread_helper+0x7/0x10
[ 0.140001] Code: c1 e8 c0 bd 18 00 8d 43 3c e8 d3 62 fc ff 89 d8 e8 87 fc ff ff e8 df a5 18 00 e9 5c ff ff ff 8b 9b 00 01 00 00 81 eb 00 01 00 00 <8b> 83 00 01 00 00 0f 18 00 90 8d 83 00 01 00 00 3b 45 e8 0f 85
[ 0.140001] EIP: [<c1068ed8>] sget+0xcf/0x333 SS:ESP 0068:f780eef4
[ 0.140001] CR2: 0000000000000000
[ 0.144031] ---[ end trace a7919e7f17c0a725 ]---
[ 0.144753] Kernel panic - not syncing: Attempted to kill init!
[ 0.145680] Pid: 1, comm: swapper Tainted: G D 2.6.31-01218-ge94d34e-dirty #3
[ 0.148004] Call Trace:
[ 0.148371] [<c101cdac>] panic+0x3f/0xd7
[ 0.148999] [<c101f1de>] do_exit+0x54/0x573
[ 0.149673] [<c101cb86>] ? print_oops_end_marker+0x1e/0x23