lirc_serial modprobe "BUG: using smp_processor_id()"

[gibboris]

Hello,
while modprobe lirc_serial (for a homemade receiver)
Tested with lirc 0.8.[56] and kernel version 2.6.3[12]
The output is attached.
(reported against 0.8.5 : http://bugs.gentoo.org/show_bug.cgi?id=285667)

cat /dev/lirc0 doesn't print anything (but I'm not sure
about the hardware quality of the receiver)

Raph

Oct 28 12:08:18 b1b1 kernel: [ 2525.244444] lirc_dev: IR Remote Control driver registered, major 61
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.109 [I] osspec.c:251: SEQNUM=798, ACTION=add, SUBSYSTEM=module, DEVPATH=/sys/module/lirc_dev, DEVNAME=, IFINDEX=0
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.109 [I] osspec.c:251: SEQNUM=799, ACTION=add, SUBSYSTEM=class, DEVPATH=/sys/class/lirc, DEVNAME=, IFINDEX=0
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.109 [I] hotplug.c:435: checking event /sys/class/lirc
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.109 [I] device.c:4905: add_dev: subsys=class sysfs_path=/sys/class/lirc dev= parent_dev=0x00000000
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.109 [D] hotplug.c:453: events queued = 0, events in progress = 0
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.109 [D] hotplug.c:458: Hotplug-queue empty now ... no hotplug events in progress
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.111 [I] osspec.c:251: SEQNUM=800, ACTION=add, SUBSYSTEM=module, DEVPATH=/sys/module/lirc_serial, DEVNAME=, IFINDEX=0
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.112 [I] osspec.c:251: SEQNUM=801, ACTION=add, SUBSYSTEM=drivers, DEVPATH=/sys/bus/platform/drivers/lirc_serial, DEVNAME=, IFINDEX=0
Oct 28 12:08:18 b1b1 kernel: [ 2525.248180] BUG: using smp_processor_id() in preemptible [00000000] code: modprobe/8790
Oct 28 12:08:18 b1b1 kernel: [ 2525.248192] caller is 0xffffffffa002a3d3
Oct 28 12:08:18 b1b1 kernel: [ 2525.248197] Pid: 8790, comm: modprobe Tainted: P           2.6.32-rc5-git1-amd64_pata #1
Oct 28 12:08:18 b1b1 kernel: [ 2525.248200] Call Trace:
Oct 28 12:08:18 b1b1 kernel: [ 2525.248218]  [<ffffffff8121d00d>] debug_smp_processor_id+0xcd/0xf0
Oct 28 12:08:18 b1b1 kernel: [ 2525.248222]  [<ffffffffa002a3d3>] 0xffffffffa002a3d3
Oct 28 12:08:18 b1b1 kernel: [ 2525.248200] Call Trace:
Oct 28 12:08:18 b1b1 kernel: [ 2525.248218]  [<ffffffff8121d00d>] debug_smp_processor_id+0xcd/0xf0
Oct 28 12:08:18 b1b1 kernel: [ 2525.248222]  [<ffffffffa002a3d3>] 0xffffffffa002a3d3
Oct 28 12:08:18 b1b1 kernel: [ 2525.248226]  [<ffffffffa0031000>] ? init_module+0x0/0x2ff [lirc_serial]
Oct 28 12:08:18 b1b1 kernel: [ 2525.248229]  [<ffffffffa0031000>] ? init_module+0x0/0x2ff [lirc_serial]
Oct 28 12:08:18 b1b1 kernel: [ 2525.248233]  [<ffffffffa003112e>] init_module+0x12e/0x2ff [lirc_serial]
Oct 28 12:08:18 b1b1 kernel: [ 2525.248237]  [<ffffffffa0031000>] ? init_module+0x0/0x2ff [lirc_serial]
Oct 28 12:08:18 b1b1 kernel: [ 2525.248233]  [<ffffffffa003112e>] init_module+0x12e/0x2ff [lirc_serial]
Oct 28 12:08:18 b1b1 kernel: [ 2525.248237]  [<ffffffffa0031000>] ? init_module+0x0/0x2ff [lirc_serial]
Oct 28 12:08:18 b1b1 kernel: [ 2525.248246]  [<ffffffff81009047>] do_one_initcall+0x37/0x190
Oct 28 12:08:18 b1b1 kernel: [ 2525.248253]  [<ffffffff81086ec6>] sys_init_module+0xd6/0x250
Oct 28 12:08:18 b1b1 kernel: [ 2525.248257]  [<ffffffff8100be2b>] system_call_fastpath+0x16/0x1b
Oct 28 12:08:18 b1b1 kernel: [ 2525.248257]  [<ffffffff8100be2b>] system_call_fastpath+0x16/0x1b
Oct 28 12:08:18 b1b1 kernel: [ 2525.248260] BUG: using smp_processor_id() in preemptible [00000000] code: modprobe/8790
Oct 28 12:08:18 b1b1 kernel: [ 2525.248263] caller is 0xffffffffa002a474
Oct 28 12:08:18 b1b1 kernel: [ 2525.248263] caller is 0xffffffffa002a474
Oct 28 12:08:18 b1b1 kernel: [ 2525.248265] Pid: 8790, comm: modprobe Tainted: P           2.6.32-rc5-git1-amd64_pata #1
Oct 28 12:08:18 b1b1 kernel: [ 2525.248267] Call Trace:
Oct 28 12:08:18 b1b1 kernel: [ 2525.248265] Pid: 8790, comm: modprobe Tainted: P           2.6.32-rc5-git1-amd64_pata #1
Oct 28 12:08:18 b1b1 kernel: [ 2525.248267] Call Trace:
Oct 28 12:08:18 b1b1 kernel: [ 2525.248270]  [<ffffffff8121d00d>] debug_smp_processor_id+0xcd/0xf0
Oct 28 12:08:18 b1b1 kernel: [ 2525.248273]  [<ffffffffa002a474>] 0xffffffffa002a474
Oct 28 12:08:18 b1b1 kernel: [ 2525.248273]  [<ffffffffa002a474>] 0xffffffffa002a474
Oct 28 12:08:18 b1b1 kernel: [ 2525.248277]  [<ffffffffa0031000>] ? init_module+0x0/0x2ff [lirc_serial]
Oct 28 12:08:18 b1b1 kernel: [ 2525.248280]  [<ffffffffa003112e>] init_module+0x12e/0x2ff [lirc_serial]
Oct 28 12:08:18 b1b1 kernel: [ 2525.248284]  [<ffffffffa0031000>] ? init_module+0x0/0x2ff [lirc_serial]
8 b1b1 kernel: [ 2525.248284]  [<ffffffffa0031000>] ? init_module+0x0/0x2ff [lirc_serial]
Oct 28 12:08:18 b1b1 kernel: [ 2525.248287]  [<ffffffff81009047>] do_one_initcall+0x37/0x190
Oct 28 12:08:18 b1b1 kernel: [ 2525.248291]  [<ffffffff81086ec6>] sys_init_module+0xd6/0x250
Oct 28 12:08:18 b1b1 kernel: [ 2525.248294]  [<ffffffff8100be2b>] system_call_fastpath+0x16/0x1b
Oct 28 12:08:18 b1b1 kernel: [ 2525.248294]  [<ffffffff8100be2b>] system_call_fastpath+0x16/0x1b
Oct 28 12:08:18 b1b1 kernel: [ 2525.248298] lirc_serial: in init_timing_params, freq=38000, duty_cycle=50, clk/jiffy=7332476, pulse=28943, space=28944, conv_us_to_clocks=2199
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.137 [I] osspec.c:251: SEQNUM=802, ACTION=add, SUBSYSTEM=platform, DEVPATH=/sys/devices/platform/lirc_serial.0, DEVNAME=, IFINDEX=0
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.137 [I] hotplug.c:435: checking event /sys/devices/platform/lirc_serial.0
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.137 [I] hotplug.c:145: /sys/devices/platform/lirc_serial.0 is a device (subsystem)
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.137 [I] hotplug.c:145: /sys/devices/platform/lirc_serial.0 is a device (subsystem)
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.137 [I] device.c:4905: add_dev: subsys=platform sysfs_path=/sys/devices/platform/lirc_serial.0 dev= parent_dev=0x00000000
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.160 [I] device.c:4753: Add callouts completed udi=/org/freedesktop/Hal/devices/platform_lirc_serial_0
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.160 [D] device_store.c:516: adding 0x6bd520 to (linux.sysfs_path,/sys/devices/platform/lirc_serial.0)
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.160 [I] hald.c:108: Added device to GDL; udi=/org/freedesktop/Hal/devices/platform_lirc_serial_0
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.160 [D] hotplug.c:453: events queued = 0, events in progress = 0
Oct 28 12:08:18 b1b1 hald[6223]: 12:08:18.160 [D] hotplug.c:458: Hotplug-queue empty now ... no hotplug events in progress
Oct 28 12:08:19 b1b1 kernel: [ 2526.139771] lirc_serial: auto-detected active high receiver
Oct 28 12:08:19 b1b1 kernel: [ 2526.139779] lirc_dev: lirc_register_driver: sample_rate: 0
Oct 28 12:08:19 b1b1 kernel: [ 2526.140003] lirc_serial $Revision: 5.104 $ registered
Oct 28 12:08:19 b1b1 kernel: [ 2526.140006] lirc_serial: type = 0
Oct 28 12:08:19 b1b1 kernel: [ 2526.140008] lirc_serial: IRQ = 4, port = 03f8
Oct 28 12:08:19 b1b1 kernel: [ 2526.140010] lirc_serial: share_irq = 0
Oct 28 12:08:19 b1b1 kernel: [ 2526.140011] lirc_serial: softcarrier = 1
Oct 28 12:08:19 b1b1 kernel: [ 2526.140008] lirc_serial: IRQ = 4, port = 03f8
Oct 28 12:08:19 b1b1 kernel: [ 2526.140010] lirc_serial: share_irq = 0
Oct 28 12:08:19 b1b1 kernel: [ 2526.140011] lirc_serial: softcarrier = 1
Oct 28 12:08:19 b1b1 hald[6223]: 12:08:19.005 [I] osspec.c:251: SEQNUM=803, ACTION=add, SUBSYSTEM=lirc, DEVPATH=/sys/devices/virtual/lirc/lirc0, DEVNAME=/dev/lirc0, IFINDEX=0
Oct 28 12:08:19 b1b1 hald[6223]: 12:08:19.005 [I] hotplug.c:435: checking event /sys/devices/virtual/lirc/lirc0
Oct 28 12:08:19 b1b1 hald[6223]: 12:08:19.005 [I] hotplug.c:145: /sys/devices/virtual/lirc/lirc0 is a device (subsystem)
Oct 28 12:08:19 b1b1 hald[6223]: 12:08:19.005 [I] hotplug.c:435: checking event /sys/devices/virtual/lirc/lirc0
Oct 28 12:08:19 b1b1 hald[6223]: 12:08:19.005 [I] hotplug.c:145: /sys/devices/virtual/lirc/lirc0 is a device (subsystem)
Oct 28 12:08:19 b1b1 hald[6223]: 12:08:19.005 [I] device.c:4905: add_dev: subsys=lirc sysfs_path=/sys/devices/virtual/lirc/lirc0 dev=/dev/lirc0 parent_dev=0x00000000
Oct 28 12:08:19 b1b1 hald[6223]: 12:08:19.005 [D] hotplug.c:453: events queued = 0, events in progress = 0
Oct 28 12:08:19 b1b1 hald[6223]: 12:08:19.005 [D] hotplug.c:453: events queued = 0, events in progress = 0
Oct 28 12:08:19 b1b1 hald[6223]: 12:08:19.005 [D] hotplug.c:458: Hotplug-queue empty now ... no hotplug events in progress

------------------------------------------------------------------------------
Come build with us! The BlackBerry(R) Developer Conference in SF, CA
is the only developer event you need to attend this year. Jumpstart your
developing skills, take BlackBerry mobile applications to market and stay
ahead of the curve. Join us from November 9 - 12, 2009. Register now!
http://p.sf.net/sfu/devconference

[Jarod Wilson]

On Oct 28, 2009, at 7:24 AM, gibboris@... wrote:

> Hello,
> while modprobe lirc_serial (for a homemade receiver)
> Tested with lirc 0.8.[56] and kernel version 2.6.3[12]
> The output is attached.
> (reported against 0.8.5 : http://bugs.gentoo.org/show_bug.cgi?id=285667 
> )

 From your dmesg attachment:

BUG: using smp_processor_id() in preemptible [00000000] code: modprobe/
8460
caller is init_module+0xb733d3/0xb73e8e [lirc_serial]

But, um, at a glance...

$ grep -c smp_processor_id lirc_serial/lirc_serial.c lirc_dev/lirc_dev.*
lirc_serial/lirc_serial.c:0
lirc_dev/lirc_dev.c:0
lirc_dev/lirc_dev.h:0

Who is calling smp_processor_id()?

--
Jarod Wilson
jarod@...




------------------------------------------------------------------------------
Come build with us! The BlackBerry(R) Developer Conference in SF, CA
is the only developer event you need to attend this year. Jumpstart your
developing skills, take BlackBerry mobile applications to market and stay
ahead of the curve. Join us from November 9 - 12, 2009. Register now!
http://p.sf.net/sfu/devconference

[gibboris]

As far as I can see,
init_timing_params() is executed after the BUG appears.
I think the cause is *somewhere* in lirc_serial.c in hardware_init_port(void)
via <linux/irq.h> or <linux/kernel.h>

Raph

On Wed, Oct 28, 2009 at 09:39:32AM -0400, Jarod Wilson wrote:

> On Oct 28, 2009, at 7:24 AM, gibboris@... wrote:
>
> >Hello,
> >while modprobe lirc_serial (for a homemade receiver)
> >Tested with lirc 0.8.[56] and kernel version 2.6.3[12]
> >The output is attached.
> >(reported against 0.8.5 :
> >http://bugs.gentoo.org/show_bug.cgi?id=285667)
>
> From your dmesg attachment:
>
> BUG: using smp_processor_id() in preemptible [00000000] code:
> modprobe/8460
> caller is init_module+0xb733d3/0xb73e8e [lirc_serial]
>
> But, um, at a glance...
>
> $ grep -c smp_processor_id lirc_serial/lirc_serial.c lirc_dev/lirc_dev.*
> lirc_serial/lirc_serial.c:0
> lirc_dev/lirc_dev.c:0
> lirc_dev/lirc_dev.h:0
>
> Who is calling smp_processor_id()?
>
> --
> Jarod Wilson
> jarod@...
>
>
>

------------------------------------------------------------------------------
Come build with us! The BlackBerry(R) Developer Conference in SF, CA
is the only developer event you need to attend this year. Jumpstart your
developing skills, take BlackBerry mobile applications to market and stay
ahead of the curve. Join us from November 9 - 12, 2009. Register now!
http://p.sf.net/sfu/devconference

[Christoph Bartelmus]

Hi!

"gibboris@..." wrote:

> As far as I can see,
> init_timing_params() is executed after the BUG appears.
> I think the cause is *somewhere* in lirc_serial.c in
> hardware_init_port(void) via <linux/irq.h> or <linux/kernel.h>

It's caused by local_irq_save(). It's bogus. Ignore it.

Chrisotph

------------------------------------------------------------------------------
Come build with us! The BlackBerry(R) Developer Conference in SF, CA
is the only developer event you need to attend this year. Jumpstart your
developing skills, take BlackBerry mobile applications to market and stay
ahead of the curve. Join us from November 9 - 12, 2009. Register now!
http://p.sf.net/sfu/devconference

[Christoph Bartelmus]

Hi!

"gibboris@..." wrote:
> while modprobe lirc_serial (for a homemade receiver)
> Tested with lirc 0.8.[56] and kernel version 2.6.3[12]
> The output is attached.
> (reported against 0.8.5 : http://bugs.gentoo.org/show_bug.cgi?id=285667)
>
> cat /dev/lirc0 doesn't print anything (but I'm not sure
> about the hardware quality of the receiver)

"auto-detected active high receiver" usually means there is no receiver  
attached. I'd say: hardware problem.

Christoph

------------------------------------------------------------------------------
Come build with us! The BlackBerry(R) Developer Conference in SF, CA
is the only developer event you need to attend this year. Jumpstart your
developing skills, take BlackBerry mobile applications to market and stay
ahead of the curve. Join us from November 9 - 12, 2009. Register now!
http://p.sf.net/sfu/devconference

[gibboris]

I will continue to work on the receiver,
ignoring the kernel warning.

Thank for the answer (and the "auto-detected active high receiver"
tip ;))

Raph

On Wed, Oct 28, 2009 at 08:16:00PM +0100, Christoph Bartelmus wrote:

> Hi!
>
> "gibboris@..." wrote:
> > while modprobe lirc_serial (for a homemade receiver)
> > Tested with lirc 0.8.[56] and kernel version 2.6.3[12]
> > The output is attached.
> > (reported against 0.8.5 : http://bugs.gentoo.org/show_bug.cgi?id=285667)
> >
> > cat /dev/lirc0 doesn't print anything (but I'm not sure
> > about the hardware quality of the receiver)
>
> "auto-detected active high receiver" usually means there is no receiver  
> attached. I'd say: hardware problem.
>
> Christoph

------------------------------------------------------------------------------
Come build with us! The BlackBerry(R) Developer Conference in SF, CA
is the only developer event you need to attend this year. Jumpstart your
developing skills, take BlackBerry mobile applications to market and stay
ahead of the curve. Join us from November 9 - 12, 2009. Register now!
http://p.sf.net/sfu/devconference