Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Richard Lemieux]

Hi,

I got some driver crashes after upgrading to kernel 2.6.32.7.  It seems that
activating either TBS8920 (DVB-S) and HVR950Q (ATSC) after the other one has
run (and is no longer in use by an application) triggers a driver crash.

Each device individually works fine (as long as the other one does not run).

I don't know how to investigate this by myself, but I am available to help.
This is not critical.  The system is otherwise stable.

Here is the last event recorded in syslog.  I activated the DVBS after
turning off applications running ATSC.

Feb  8 16:18:16 pc3 kernel: DVB: registering adapter 1 frontend 0 (Auvitek 
AU8522 QAM/8VSB Frontend)...
Feb  8 21:37:17 pc3 kernel: cx88[0]/0: unknown tv audio mode [0]
Feb  8 23:00:45 pc3 kernel: cx88[0]/0: unknown tv audio mode [0]
Feb  8 23:01:24 pc3 last message repeated 2 times
Feb  8 23:04:00 pc3 kernel: BUG: unable to handle kernel NULL pointer 
dereference at 00000004
Feb  8 23:04:00 pc3 kernel: IP: [<c11ae628>] firmware_loading_store+0x68/0x1a0
Feb  8 23:04:00 pc3 kernel: *pdpt = 000000003650e001 *pde = 0000000000000000
Feb  8 23:04:00 pc3 kernel: Oops: 0000 [#1] SMP
Feb  8 23:04:00 pc3 kernel: last sysfs file: 
/sys/class/firmware/0000:08:00.0/loading
Feb  8 23:04:00 pc3 kernel: Modules linked in: xc5000 tuner au8522 au0828 
videobuf_vmalloc snd_seq rtc hid_logitech ext4 jbd2 crc16 nls_iso8859_1 
nls_cp437 bsd_comp ppp_deflate zlib_deflate ppp_async crc_ccitt ppp_generic slhc 
parport_pc lp parport joydev usb_storage usblp snd_usb_audio snd_usb_lib 
snd_rawmidi snd_seq_device usbhid snd_hwdep cx24116 cx88_dvb cx88_vp3054_i2c 
videobuf_dvb dvb_core snd_hda_codec_realtek snd_hda_intel snd_hda_codec 
snd_pcm_oss cx8802 snd_mixer_oss cx8800 cx88xx snd_pcm ir_common i2c_i801 
i2c_algo_bit v4l2_common snd_timer tveeprom ohci1394 sky2 ehci_hcd snd videodev 
v4l1_compat videobuf_dma_sg btcx_risc ieee1394 8250_pnp 8250 serial_core 
uhci_hcd bitrev nvidia(P) crc32 agpgart videobuf_core soundcore snd_page_alloc 
i2c_core usbcore sg evdev
Feb  8 23:04:00 pc3 kernel:
Feb  8 23:04:00 pc3 kernel: Pid: 6390, comm: firmware.agent Tainted: P 
  (2.6.32.7 #1) P5E WS Pro
Feb  8 23:04:00 pc3 kernel: EIP: 0060:[<c11ae628>] EFLAGS: 00010296 CPU: 1
Feb  8 23:04:00 pc3 kernel: EIP is at firmware_loading_store+0x68/0x1a0
Feb  8 23:04:00 pc3 kernel: EAX: 00000000 EBX: f66a1140 ECX: 00000002 EDX: 2f1dc161
Feb  8 23:04:00 pc3 kernel: ESI: f7513440 EDI: f05b8380 EBP: 00000002 ESP: f0c15f1c
Feb  8 23:04:00 pc3 kernel:  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
Feb  8 23:04:00 pc3 kernel: Process firmware.agent (pid: 6390, ti=f0c14000 
task=f6e65850 task.ti=f0c14000)
Feb  8 23:04:00 pc3 kernel: Stack:
Feb  8 23:04:00 pc3 kernel:  00000161 80000000 0810b408 c430ed60 c10713d2 
c11ae5c0 00000002 c13ab7c0
Feb  8 23:04:00 pc3 kernel: <0> 00000002 c11a6965 00000002 f66dc940 f75242f8 
c10cc0d9 00000002 0810b408
Feb  8 23:04:00 pc3 kernel: <0> f66dc954 f7513448 f0c6cac0 00000002 0810b408 
c10cc040 c1086ff0 f0c15f9c
Feb  8 23:04:00 pc3 kernel: Call Trace:
Feb  8 23:04:00 pc3 kernel:  [<c10713d2>] ? handle_mm_fault+0x612/0x9f0
Feb  8 23:04:00 pc3 kernel:  [<c11ae5c0>] ? firmware_loading_store+0x0/0x1a0
Feb  8 23:04:00 pc3 kernel:  [<c11a6965>] ? dev_attr_store+0x25/0x40
Feb  8 23:04:00 pc3 kernel:  [<c10cc0d9>] ? sysfs_write_file+0x99/0x100
Feb  8 23:04:00 pc3 kernel:  [<c10cc040>] ? sysfs_write_file+0x0/0x100
Feb  8 23:04:00 pc3 kernel:  [<c1086ff0>] ? vfs_write+0xa0/0x160
Feb  8 23:04:00 pc3 kernel:  [<c1087171>] ? sys_write+0x41/0x70
Feb  8 23:04:00 pc3 kernel:  [<c1002e08>] ? sysenter_do_call+0x12/0x26
Feb  8 23:04:00 pc3 kernel: Code: 04 e8 dd c8 ec ff 8b 53 40 31 c9 8b 43 3c 8b 
7b 34 c7 04 24 61 01 00 00 c7 44 24 04 00 00 00 80 e8 8e cf ec ff 89 47 04 8b 43 
34 <8b> 78 04 85 ff 0f 84 f4 00 00 00 c7 43 44 00 00 00 00 8d 43 04
Feb  8 23:04:00 pc3 kernel: EIP: [<c11ae628>] firmware_loading_store+0x68/0x1a0 
SS:ESP 0068:f0c15f1c
Feb  8 23:04:00 pc3 kernel: CR2: 0000000000000004
Feb  8 23:04:00 pc3 kernel: ---[ end trace c07258db2013e403 ]---


Here is another event.  I booted in between.  The system is stable otherwise.


Feb  7 14:15:06 pc3 kernel: DVB: registering adapter 1 frontend 0 (Auvitek
AU8522 QAM/8VSB Frontend)...
Feb  7 14:15:30 pc3 udevd-event[15971]: run_program: '/lib/udev/firmware.sh'
abnormal exit
Feb  7 14:15:30 pc3 kernel: BUG: unable to handle kernel NULL pointer
dereference at 00000004
Feb  7 14:15:30 pc3 kernel: IP: [<c11ae622>] firmware_loading_store+0x62/0x1a0
Feb  7 14:15:30 pc3 kernel: *pdpt = 0000000036bc4001 *pde = 0000000000000000
Feb  7 14:15:30 pc3 kernel: Oops: 0002 [#1] SMP
Feb  7 14:15:30 pc3 kernel: last sysfs file: /sys/class/firmware/7-4/loading
Feb  7 14:15:30 pc3 kernel: Modules linked in: snd_usb_audio snd_usb_lib
snd_rawmidi snd_hwdep xc5000 tuner au8522 au0828 videobuf_vmalloc nvidia(P)
snd_seq snd_seq_device rtc hid_logitech ext4 jbd2 crc16 nls_iso8859_1 nls_cp437
bsd_comp ppp_deflate zlib_deflate ppp_async crc_ccitt ppp_generic slhc agpgart
parport_pc lp parport joydev usb_storage usbhid usblp cx24116 cx88_dvb
cx88_vp3054_i2c videobuf_dvb dvb_core snd_hda_codec_realtek snd_hda_intel cx8802
cx8800 snd_hda_codec cx88xx snd_pcm_oss ir_common snd_mixer_oss i2c_algo_bit
ohci1394 v4l2_common tveeprom i2c_i801 snd_pcm 8250_pnp 8250 serial_core
videodev v4l1_compat videobuf_dma_sg i2c_core sky2 videobuf_core ehci_hcd
ieee1394 btcx_risc snd_timer snd bitrev crc32 soundcore snd_page_alloc uhci_hcd
usbcore sg evdev [last unloaded: nvidia]
Feb  7 14:15:30 pc3 kernel:
Feb  7 14:15:30 pc3 kernel: Pid: 15972, comm: firmware.sh Tainted: P
(2.6.32.7 #1) P5E WS Pro
Feb  7 14:15:30 pc3 kernel: EIP: 0060:[<c11ae622>] EFLAGS: 00010296 CPU: 1
Feb  7 14:15:30 pc3 kernel: EIP is at firmware_loading_store+0x62/0x1a0
Feb  7 14:15:30 pc3 kernel: EAX: 00000000 EBX: f2428ac0 ECX: 00000000 EDX: e19bc000
Feb  7 14:15:30 pc3 kernel: ESI: ed92fe00 EDI: 00000000 EBP: 00000002 ESP: e19bdf1c
Feb  7 14:15:30 pc3 kernel:  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
Feb  7 14:15:30 pc3 kernel: Process firmware.sh (pid: 15972, ti=e19bc000
task=f6fa2760 task.ti=e19bc000)
Feb  7 14:15:30 pc3 kernel: Stack:
Feb  7 14:15:30 pc3 kernel:  00000161 80000000 0810b408 c4ff6dc0 c10713d2
c11ae5c0 00000002 c13ab7c0
Feb  7 14:15:30 pc3 kernel: <0> 00000002 c11a6965 00000002 f3f387c0 f147d744
c10cc0d9 00000002 0810b408
Feb  7 14:15:30 pc3 kernel: <0> f3f387d4 ed92fe08 ed91d940 00000002 0810b408
c10cc040 c1086ff0 e19bdf9c
Feb  7 14:15:30 pc3 kernel: Call Trace:
Feb  7 14:15:30 pc3 kernel:  [<c10713d2>] ? handle_mm_fault+0x612/0x9f0
Feb  7 14:15:30 pc3 kernel:  [<c11ae5c0>] ? firmware_loading_store+0x0/0x1a0
Feb  7 14:15:30 pc3 kernel:  [<c11a6965>] ? dev_attr_store+0x25/0x40
Feb  7 14:15:30 pc3 kernel:  [<c10cc0d9>] ? sysfs_write_file+0x99/0x100
Feb  7 14:15:30 pc3 kernel:  [<c10cc040>] ? sysfs_write_file+0x0/0x100
Feb  7 14:15:30 pc3 kernel:  [<c1086ff0>] ? vfs_write+0xa0/0x160
Feb  7 14:15:30 pc3 kernel:  [<c1087171>] ? sys_write+0x41/0x70
Feb  7 14:15:30 pc3 kernel:  [<c1002e08>] ? sysenter_do_call+0x12/0x26
Feb  7 14:15:30 pc3 kernel: Code: 62 8b 43 34 8b 40 04 e8 dd c8 ec ff 8b 53 40
31 c9 8b 43 3c 8b 7b 34 c7 04 24 61 01 00 00 c7 44 24 04 00 00 00 80 e8 8e cf ec
ff <89> 47 04 8b 43 34 8b 78 04 85 ff 0f 84 f4 00 00 00 c7 43 44 00
Feb  7 14:15:30 pc3 kernel: EIP: [<c11ae622>] firmware_loading_store+0x62/0x1a0
SS:ESP 0068:e19bdf1c
Feb  7 14:15:30 pc3 kernel: CR2: 0000000000000004
Feb  7 14:15:30 pc3 kernel: ---[ end trace dfa955c34e6458e9 ]---

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Devin Heitmueller]

On Mon, Feb 8, 2010 at 11:43 PM, Richard Lemieux <rlemieu@cooptel.qc.ca> wrote:
> Hi,
>
> I got some driver crashes after upgrading to kernel 2.6.32.7.  It seems that
> activating either TBS8920 (DVB-S) and HVR950Q (ATSC) after the other one has
> run (and is no longer in use by an application) triggers a driver crash.

Hello Richard,

Have you tried any other kernel version?  For example, do you know
that it works properly in 2.6.32.6?

Can you bisect and see when the problem was introduced?

Devin

-- 
Devin J. Heitmueller - Kernel Labs
http://www.kernellabs.com

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Richard Lemieux]

Hi Devin,

I was previously running kernel vmlinux-2.6.29.5.  I notice there was a major
reorganization of some of the media structure between 2.6.29 and 2.6.32.
Can you tell me at wich kernel version the change occured so I can start from there.

Richard

Devin Heitmueller wrote:
> On Mon, Feb 8, 2010 at 11:43 PM, Richard Lemieux <rlemieu@cooptel.qc.ca> wrote:
>> Hi,
>>
>> I got some driver crashes after upgrading to kernel 2.6.32.7.  It seems that
>> activating either TBS8920 (DVB-S) and HVR950Q (ATSC) after the other one has
>> run (and is no longer in use by an application) triggers a driver crash.
> 
> Hello Richard,
> 
> Have you tried any other kernel version?  For example, do you know
> that it works properly in 2.6.32.6?
> 
> Can you bisect and see when the problem was introduced?
> 
> Devin
> 

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Devin Heitmueller]

On Tue, Feb 9, 2010 at 8:44 AM, Richard Lemieux <rlemieu@cooptel.qc.ca> wrote:
> Hi Devin,
>
> I was previously running kernel vmlinux-2.6.29.5.  I notice there was a
> major
> reorganization of some of the media structure between 2.6.29 and 2.6.32.
> Can you tell me at wich kernel version the change occured so I can start
> from there.

Hi Richard,

The only "major reorganization" in that time period I can think of is
a couple of the files related to IR support were moved.

Further, the problem appears to be in the implementation of
request_firmware() and doesn't look specific to any changes in the
v4l-dvb tree.

All I can suggest at this point is you try to narrow down what release
the breakage was introduced in, at which point we can take a look at
what changed.

Devin

-- 
Devin J. Heitmueller - Kernel Labs
http://www.kernellabs.com

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Richard Lemieux]

Hi,

I tried something simple with three kernel versions:

2.6.30, 2.6.31, and 2.6.32.7.

But I can't reproduce the problem that way.

Just after booting I run alternatively

/opt/dvb-apps/bin/szap -a 0 -r "CCTV 4"
/opt/dvb-apps/bin/azap -a 1 -r "57.1"

and then I run them concurrently

and finally I disconnect the USB tuner and replug and retry the 'azap'

I did not get any crash yet.

So there is likely some other "environmental" condition that is relevant.

I will continue using 2.6.32.7.  Whenever I meet the problem I will
take note of the environment and try to reproduce the same environment with
other versions of the kernel.

Thanks

> 
> The only "major reorganization" in that time period I can think of is
> a couple of the files related to IR support were moved.
> 
> Further, the problem appears to be in the implementation of
> request_firmware() and doesn't look specific to any changes in the
> v4l-dvb tree.
> 
> All I can suggest at this point is you try to narrow down what release
> the breakage was introduced in, at which point we can take a look at
> what changed.
> 
> Devin
> 

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Andy Walls]

On Mon, 2010-02-08 at 23:43 -0500, Richard Lemieux wrote:
> Hi,
> 
> I got some driver crashes after upgrading to kernel 2.6.32.7.  It seems that
> activating either TBS8920 (DVB-S) and HVR950Q (ATSC) after the other one has
> run (and is no longer in use by an application) triggers a driver crash.
>
> Each device individually works fine (as long as the other one does not run).

Both Ooops below are related to userspace loading of firmware for the
HVR-950Q.


> I don't know how to investigate this by myself, but I am available to help.
> This is not critical.  The system is otherwise stable.
> 
> Here is the last event recorded in syslog.  I activated the DVBS after
> turning off applications running ATSC.
> 
> Feb  8 16:18:16 pc3 kernel: DVB: registering adapter 1 frontend 0 (Auvitek 
> AU8522 QAM/8VSB Frontend)...
> Feb  8 21:37:17 pc3 kernel: cx88[0]/0: unknown tv audio mode [0]
> Feb  8 23:00:45 pc3 kernel: cx88[0]/0: unknown tv audio mode [0]
> Feb  8 23:01:24 pc3 last message repeated 2 times
> Feb  8 23:04:00 pc3 kernel: BUG: unable to handle kernel NULL pointer 
> dereference at 00000004
> Feb  8 23:04:00 pc3 kernel: IP: [<c11ae628>] firmware_loading_store+0x68/0x1a0
> Feb  8 23:04:00 pc3 kernel: *pdpt = 000000003650e001 *pde = 0000000000000000
> Feb  8 23:04:00 pc3 kernel: Oops: 0000 [#1] SMP
> Feb  8 23:04:00 pc3 kernel: last sysfs file: 
> /sys/class/firmware/0000:08:00.0/loading
> Feb  8 23:04:00 pc3 kernel: Modules linked in: xc5000 tuner au8522 au0828 
> videobuf_vmalloc snd_seq rtc hid_logitech ext4 jbd2 crc16 nls_iso8859_1 
> nls_cp437 bsd_comp ppp_deflate zlib_deflate ppp_async crc_ccitt ppp_generic slhc 
> parport_pc lp parport joydev usb_storage usblp snd_usb_audio snd_usb_lib 
> snd_rawmidi snd_seq_device usbhid snd_hwdep cx24116 cx88_dvb cx88_vp3054_i2c 
> videobuf_dvb dvb_core snd_hda_codec_realtek snd_hda_intel snd_hda_codec 
> snd_pcm_oss cx8802 snd_mixer_oss cx8800 cx88xx snd_pcm ir_common i2c_i801 
> i2c_algo_bit v4l2_common snd_timer tveeprom ohci1394 sky2 ehci_hcd snd videodev 
> v4l1_compat videobuf_dma_sg btcx_risc ieee1394 8250_pnp 8250 serial_core 
> uhci_hcd bitrev nvidia(P) crc32 agpgart videobuf_core soundcore snd_page_alloc 
> i2c_core usbcore sg evdev
> Feb  8 23:04:00 pc3 kernel:
> Feb  8 23:04:00 pc3 kernel: Pid: 6390, comm: firmware.agent Tainted: P 
>   (2.6.32.7 #1) P5E WS Pro
> Feb  8 23:04:00 pc3 kernel: EIP: 0060:[<c11ae628>] EFLAGS: 00010296 CPU: 1
> Feb  8 23:04:00 pc3 kernel: EIP is at firmware_loading_store+0x68/0x1a0
> Feb  8 23:04:00 pc3 kernel: EAX: 00000000 EBX: f66a1140 ECX: 00000002 EDX: 2f1dc161
> Feb  8 23:04:00 pc3 kernel: ESI: f7513440 EDI: f05b8380 EBP: 00000002 ESP: f0c15f1c
> Feb  8 23:04:00 pc3 kernel:  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
> Feb  8 23:04:00 pc3 kernel: Process firmware.agent (pid: 6390, ti=f0c14000 
> task=f6e65850 task.ti=f0c14000)
> Feb  8 23:04:00 pc3 kernel: Stack:
> Feb  8 23:04:00 pc3 kernel:  00000161 80000000 0810b408 c430ed60 c10713d2 
> c11ae5c0 00000002 c13ab7c0
> Feb  8 23:04:00 pc3 kernel: <0> 00000002 c11a6965 00000002 f66dc940 f75242f8 
> c10cc0d9 00000002 0810b408
> Feb  8 23:04:00 pc3 kernel: <0> f66dc954 f7513448 f0c6cac0 00000002 0810b408 
> c10cc040 c1086ff0 f0c15f9c
> Feb  8 23:04:00 pc3 kernel: Call Trace:
> Feb  8 23:04:00 pc3 kernel:  [<c10713d2>] ? handle_mm_fault+0x612/0x9f0
> Feb  8 23:04:00 pc3 kernel:  [<c11ae5c0>] ? firmware_loading_store+0x0/0x1a0
> Feb  8 23:04:00 pc3 kernel:  [<c11a6965>] ? dev_attr_store+0x25/0x40
> Feb  8 23:04:00 pc3 kernel:  [<c10cc0d9>] ? sysfs_write_file+0x99/0x100
> Feb  8 23:04:00 pc3 kernel:  [<c10cc040>] ? sysfs_write_file+0x0/0x100
> Feb  8 23:04:00 pc3 kernel:  [<c1086ff0>] ? vfs_write+0xa0/0x160
> Feb  8 23:04:00 pc3 kernel:  [<c1087171>] ? sys_write+0x41/0x70
> Feb  8 23:04:00 pc3 kernel:  [<c1002e08>] ? sysenter_do_call+0x12/0x26
> Feb  8 23:04:00 pc3 kernel: Code: 04 e8 dd c8 ec ff 8b 53 40 31 c9 8b 43 3c 8b 
> 7b 34 c7 04 24 61 01 00 00 c7 44 24 04 00 00 00 80 e8 8e cf ec ff 89 47 04 8b 43 
> 34 <8b> 78 04 85 ff 0f 84 f4 00 00 00 c7 43 44 00 00 00 00 8d 43 04
> Feb  8 23:04:00 pc3 kernel: EIP: [<c11ae628>] firmware_loading_store+0x68/0x1a0 
> SS:ESP 0068:f0c15f1c
> Feb  8 23:04:00 pc3 kernel: CR2: 0000000000000004
> Feb  8 23:04:00 pc3 kernel: ---[ end trace c07258db2013e403 ]---
> 

So we know the oops happens in
linux/drivers/base/firmware_class.c:firmware_loading_store().  This is
the function that handles the firmware loading status feedback from
userspace.  udev writes "1" to a device specific sysfs node when
firmware loading begins, and writes "0" to that sysfs node when the
firmware copying is completed by udev.

You can use udevadm as root to monitor udev events.
You can examine /lib/udev/firmware.sh to see the script that udev runs
in response to firmware load requests that you see with udevadm.

Anyway here is the source code that Ooops'ed:

/**
 * firmware_loading_store - set value in the 'loading' control file
 * @dev: device pointer
 * @attr: device attribute pointer
 * @buf: buffer to scan for loading control value
 * @count: number of bytes in @buf
 *      
 *      The relevant values are:
 *      
 *       1: Start a load, discarding any previous partial load.
 *       0: Conclude the load and hand the data to the driver code.
 *      -1: Conclude the load with an error and discard any written data.
 **/            
static ssize_t firmware_loading_store(struct device *dev,
                                      struct device_attribute *attr,
                                      const char *buf, size_t count)
{       
        struct firmware_priv *fw_priv = dev_get_drvdata(dev);
        int loading = simple_strtol(buf, NULL, 10);
        int i;

        switch (loading) {
        case 1:
                ...
                break;
        case 0:
               if (test_bit(FW_STATUS_LOADING, &fw_priv->status)) {
                        vfree(fw_priv->fw->data);
                        fw_priv->fw->data = vmap(fw_priv->pages,
                                                 fw_priv->nr_pages,
                                                 0, PAGE_KERNEL_RO);
                        if (!fw_priv->fw->data) {                              <------------ Ooops here: fw_priv->fw is NULL
                               dev_err(dev, "%s: vmap() failed\n", __func__);
                                goto err;
                        }
                        /* Pages will be freed by vfree() */
                        fw_priv->page_array_size = 0;
               ....


Here's how I know that:

$ echo "00 04 e8 dd c8 ec ff 8b 53 40 31 c9 8b 43 3c 8b 7b 34 c7 04 24
61 01 00 00 c7 44 24 04 00 00 00 80 e8 8e cf ec ff 89 47 04 8b 43 34 8b
78 04 85 ff 0f 84 f4 00 00 00 c7 43 44 00 00 00 00 8d 43 04" | xxd -r -g
1 -c 64 > foo.bin

$ objdump -D -b binary -m i386 foo.bin --adjust-vma=0x3d --start-addr=0x3e

foo.bin:     file format binary

Disassembly of section .data:

0000003e <.data+0x1>:
  3e:	e8 dd c8 ec ff       	call   0xffecc920
  43:	8b 53 40             	mov    0x40(%ebx),%edx;  fw_priv->nr_pages
  46:	31 c9                	xor    %ecx,%ecx;        0
  48:	8b 43 3c             	mov    0x3c(%ebx),%eax;  fw_priv->pages
  4b:	8b 7b 34             	mov    0x34(%ebx),%edi;  fw_priv->fw
  4e:	c7 04 24 61 01 00 00 	movl   $0x161,(%esp);    PAGE_KERNEL_RO
  55:	c7 44 24 04 00 00 00 	movl   $0x80000000,0x4(%esp); ???
  5c:	80 
  5d:	e8 8e cf ec ff       	call   0xffeccff0;       vmap(fw_priv->pages, fw_priv->nr_pages, 0, PAGE_KERNEL_RO);
  62:	89 47 04             	mov    %eax,0x4(%edi);   fw_priv->fw->data = vmap(fw_priv->pages, fw_priv->nr_pages, 0, PAGE_KERNEL_RO);
  65:	8b 43 34             	mov    0x34(%ebx),%eax;  fw_priv->fw
  68:	8b 78 04             	mov    0x4(%eax),%edi     <--- Ooops here; fw_priv->fw->data and %eax (fw_priv->fw) is NULL
  6b:	85 ff                	test   %edi,%edi;        if (!fw_priv->fw->data) {
  6d:	0f 84 f4 00 00 00    	je     0x167
  73:	c7 43 44 00 00 00 00 	movl   $0x0,0x44(%ebx);  fw_priv->page_array_size = 0;
  7a:	8d 43 04             	lea    0x4(%ebx),%eax


So there seems to be some sort of race condition where fw_priv->fw is
getting deallocated while still being operated upon.

<wild speculation>
This means the xc5000 or au0828 driver or might need to be examined to
see how this race could happen.  Maybe something odd like
xc5000_fwupload being called concurrently? It could be a USB subsystem
thing too.
</wild speculation>

I'm out of my depth on how the HVR-950Q works.  Devin would be the
expert here.


> Here is another event.  I booted in between.  The system is stable otherwise.
> 
> 
> Feb  7 14:15:06 pc3 kernel: DVB: registering adapter 1 frontend 0 (Auvitek
> AU8522 QAM/8VSB Frontend)...
> Feb  7 14:15:30 pc3 udevd-event[15971]: run_program: '/lib/udev/firmware.sh'
> abnormal exit
> Feb  7 14:15:30 pc3 kernel: BUG: unable to handle kernel NULL pointer
> dereference at 00000004
> Feb  7 14:15:30 pc3 kernel: IP: [<c11ae622>] firmware_loading_store+0x62/0x1a0
> Feb  7 14:15:30 pc3 kernel: *pdpt = 0000000036bc4001 *pde = 0000000000000000
> Feb  7 14:15:30 pc3 kernel: Oops: 0002 [#1] SMP
> Feb  7 14:15:30 pc3 kernel: last sysfs file: /sys/class/firmware/7-4/loading
> Feb  7 14:15:30 pc3 kernel: Modules linked in: snd_usb_audio snd_usb_lib
> snd_rawmidi snd_hwdep xc5000 tuner au8522 au0828 videobuf_vmalloc nvidia(P)
> snd_seq snd_seq_device rtc hid_logitech ext4 jbd2 crc16 nls_iso8859_1 nls_cp437
> bsd_comp ppp_deflate zlib_deflate ppp_async crc_ccitt ppp_generic slhc agpgart
> parport_pc lp parport joydev usb_storage usbhid usblp cx24116 cx88_dvb
> cx88_vp3054_i2c videobuf_dvb dvb_core snd_hda_codec_realtek snd_hda_intel cx8802
> cx8800 snd_hda_codec cx88xx snd_pcm_oss ir_common snd_mixer_oss i2c_algo_bit
> ohci1394 v4l2_common tveeprom i2c_i801 snd_pcm 8250_pnp 8250 serial_core
> videodev v4l1_compat videobuf_dma_sg i2c_core sky2 videobuf_core ehci_hcd
> ieee1394 btcx_risc snd_timer snd bitrev crc32 soundcore snd_page_alloc uhci_hcd
> usbcore sg evdev [last unloaded: nvidia]
> Feb  7 14:15:30 pc3 kernel:
> Feb  7 14:15:30 pc3 kernel: Pid: 15972, comm: firmware.sh Tainted: P
> (2.6.32.7 #1) P5E WS Pro
> Feb  7 14:15:30 pc3 kernel: EIP: 0060:[<c11ae622>] EFLAGS: 00010296 CPU: 1
> Feb  7 14:15:30 pc3 kernel: EIP is at firmware_loading_store+0x62/0x1a0
> Feb  7 14:15:30 pc3 kernel: EAX: 00000000 EBX: f2428ac0 ECX: 00000000 EDX: e19bc000
> Feb  7 14:15:30 pc3 kernel: ESI: ed92fe00 EDI: 00000000 EBP: 00000002 ESP: e19bdf1c
> Feb  7 14:15:30 pc3 kernel:  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
> Feb  7 14:15:30 pc3 kernel: Process firmware.sh (pid: 15972, ti=e19bc000
> task=f6fa2760 task.ti=e19bc000)
> Feb  7 14:15:30 pc3 kernel: Stack:
> Feb  7 14:15:30 pc3 kernel:  00000161 80000000 0810b408 c4ff6dc0 c10713d2
> c11ae5c0 00000002 c13ab7c0
> Feb  7 14:15:30 pc3 kernel: <0> 00000002 c11a6965 00000002 f3f387c0 f147d744
> c10cc0d9 00000002 0810b408
> Feb  7 14:15:30 pc3 kernel: <0> f3f387d4 ed92fe08 ed91d940 00000002 0810b408
> c10cc040 c1086ff0 e19bdf9c
> Feb  7 14:15:30 pc3 kernel: Call Trace:
> Feb  7 14:15:30 pc3 kernel:  [<c10713d2>] ? handle_mm_fault+0x612/0x9f0
> Feb  7 14:15:30 pc3 kernel:  [<c11ae5c0>] ? firmware_loading_store+0x0/0x1a0
> Feb  7 14:15:30 pc3 kernel:  [<c11a6965>] ? dev_attr_store+0x25/0x40
> Feb  7 14:15:30 pc3 kernel:  [<c10cc0d9>] ? sysfs_write_file+0x99/0x100
> Feb  7 14:15:30 pc3 kernel:  [<c10cc040>] ? sysfs_write_file+0x0/0x100
> Feb  7 14:15:30 pc3 kernel:  [<c1086ff0>] ? vfs_write+0xa0/0x160
> Feb  7 14:15:30 pc3 kernel:  [<c1087171>] ? sys_write+0x41/0x70
> Feb  7 14:15:30 pc3 kernel:  [<c1002e08>] ? sysenter_do_call+0x12/0x26
> Feb  7 14:15:30 pc3 kernel: Code: 62 8b 43 34 8b 40 04 e8 dd c8 ec ff 8b 53 40
> 31 c9 8b 43 3c 8b 7b 34 c7 04 24 61 01 00 00 c7 44 24 04 00 00 00 80 e8 8e cf ec
> ff <89> 47 04 8b 43 34 8b 78 04 85 ff 0f 84 f4 00 00 00 c7 43 44 00
> Feb  7 14:15:30 pc3 kernel: EIP: [<c11ae622>] firmware_loading_store+0x62/0x1a0
> SS:ESP 0068:e19bdf1c
> Feb  7 14:15:30 pc3 kernel: CR2: 0000000000000004
> Feb  7 14:15:30 pc3 kernel: ---[ end trace dfa955c34e6458e9 ]---


Same function.  Similar oops as fw_priv->fw is NULL, only this time it
happens two lines of assembly code earlier.  This definitely smells like
a race.

Your ability to reproduce this should be rather limited.  If you know
steps that make it more likely to reproduce, please remember what they
are.

Regards,
Andy

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Richard Lemieux]

Andy,

This is a great answer!  Thanks very much.  When I get into this situation again
I will know what to look for.

A possible reason why I got into this problem in the first place is that I tried
many combinations of parameters with mplayer and azap in order to learn how
to use the USB tuner in both the ATSC and the NTSC mode.  I will look back
in the terminal history to see if I can find anything.

Regards,
Richard

Andy Walls wrote:
>
...

> Your ability to reproduce this should be rather limited.  If you know
> steps that make it more likely to reproduce, please remember what they
> are.
> 
> Regards,
> Andy
> 
> 
> 
> 

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Devin Heitmueller]

On Tue, Feb 9, 2010 at 10:05 PM, Richard Lemieux <rlemieu@cooptel.qc.ca> wrote:
> Andy,
>
> This is a great answer!  Thanks very much.  When I get into this situation
> again
> I will know what to look for.
>
> A possible reason why I got into this problem in the first place is that I
> tried
> many combinations of parameters with mplayer and azap in order to learn how
> to use the USB tuner in both the ATSC and the NTSC mode.  I will look back
> in the terminal history to see if I can find anything.

I think the key to figuring out the bug at this point is you finding a
sequence where you can reliably reproduce the oops.  If we have that,
then I can start giving you some code to try which we can see if it
addresses the problem.

For example, I would start by giving you a fix which results in us not
calling the firmware release if the request_firmware() call failed,
but it wouldn't be much help if you could not definitively tell me if
the problem is fixed.

Devin


-- 
Devin J. Heitmueller - Kernel Labs
http://www.kernellabs.com

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Andy Walls]

On Tue, 2010-02-09 at 22:12 -0500, Devin Heitmueller wrote:
> On Tue, Feb 9, 2010 at 10:05 PM, Richard Lemieux <rlemieu@cooptel.qc.ca> wrote:
> > Andy,
> >
> > This is a great answer!  Thanks very much.  When I get into this situation
> > again
> > I will know what to look for.
> >
> > A possible reason why I got into this problem in the first place is that I
> > tried
> > many combinations of parameters with mplayer and azap in order to learn how
> > to use the USB tuner in both the ATSC and the NTSC mode.  I will look back
> > in the terminal history to see if I can find anything.
> 
> I think the key to figuring out the bug at this point is you finding a
> sequence where you can reliably reproduce the oops.  If we have that,
> then I can start giving you some code to try which we can see if it
> addresses the problem.

Also the verbose output of udevadm monitor (see man udevadm) would help
us get a feeling for the timing relationships for the firmware
requests.


> For example, I would start by giving you a fix which results in us not
> calling the firmware release if the request_firmware() call failed,
> but it wouldn't be much help if you could not definitively tell me if
> the problem is fixed.

Definitely.


Also, given the slow loading due to a chip I2C limitation, Richard, you
may just want to increase your firmware loading timeout:

$ su - root
Password:

# cat /sys/class/firmware/timeout 
10

# echo 90 > /sys/class/firmware/timeout

# cat /sys/class/firmware/timeout 
90

And see if the problem "goes away".  Again having some sort of steps to
reliably reproduce the oops would be helpful in determining the efficacy
of such a work around.

Regards,
Andy

> Devin

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Andy Walls]

On Tue, 2010-02-09 at 22:12 -0500, Devin Heitmueller wrote:
> On Tue, Feb 9, 2010 at 10:05 PM, Richard Lemieux <rlemieu@cooptel.qc.ca> wrote:
> > Andy,
> >
> > This is a great answer!  Thanks very much.  When I get into this situation
> > again
> > I will know what to look for.
> >
> > A possible reason why I got into this problem in the first place is that I
> > tried
> > many combinations of parameters with mplayer and azap in order to learn how
> > to use the USB tuner in both the ATSC and the NTSC mode.  I will look back
> > in the terminal history to see if I can find anything.
> 
> I think the key to figuring out the bug at this point is you finding a
> sequence where you can reliably reproduce the oops.  If we have that,
> then I can start giving you some code to try which we can see if it
> addresses the problem.
> 
> For example, I would start by giving you a fix which results in us not
> calling the firmware release if the request_firmware() call failed,
> but it wouldn't be much help if you could not definitively tell me if
> the problem is fixed.


For the oops analysis here:

http://article.gmane.org/gmane.linux.drivers.video-input-infrastructure/15954


I will also note that the file scope "fw_lock" mutex is rather
inconsistently used in
linux/drivers/base/fw_class.c:firmware_loading_store().  (I guess for
not wanting to consume the timeout interval with sleeping?)

The mutex protects "case 1:", but all other cases appear to be only
protected by atomic status bit checks that can fall through to
fw_load_abort() which complete()'s the fw_priv->completion.

Also not that in the _request_firmware() this sequence is the only place
a once good "fw_priv->fw" pointer is set to NULL:

        mutex_lock(&fw_lock);
        if (!fw_priv->fw->size || test_bit(FW_STATUS_ABORT, &fw_priv->status)) {
                retval = -ENOENT;
                release_firmware(fw_priv->fw);
                *firmware_p = NULL;
        }
        fw_priv->fw = NULL;     <--------------- The only place it is set to NULL
        mutex_unlock(&fw_lock);


So if the timeout timer fires at nearly the same time as udev coming in
and say "I'm done loading" without holding the mutex, one can run into
the Ooops.  Not only that, I think the above code can leak memory under
some circumstances when the "if" clause is not satisfied.

I think this really is a firmware_class.c issue.  I think the "just
right" firmware loading timeouts and the particular computer system
responsiveness, make this Ooops possible.  However, I'm amazed that a
single person has tripped it more than once.

Revising the locking in linux/drivers/base/firmware_class.c should fix
the problem.

I don't believe this comment in the code now:

/* fw_lock could be moved to 'struct firmware_priv' but since it is just
 * guarding for corner cases a global lock should be OK */
static DEFINE_MUTEX(fw_lock);

struct firmware_priv {
        char *fw_id;
	...

And since "f_priv" is dynamically created and destroyed by
request_firmware() I see no harm in 

1. moving the mutex into struct firmware_priv
2. just always just grabbing an almost never contended mutex
3. getting rid of the file scope fw_lock.

except grabbing a mutex() while the timeout timer is running during
loading, means one *could* sleep for a while consuming the timeout
interval.



Or am I out to lunch?

Regards,
Andy

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Greg KH]

On Wed, Feb 10, 2010 at 10:34:56AM -0500, Andy Walls wrote:
> On Tue, 2010-02-09 at 22:12 -0500, Devin Heitmueller wrote:
> > On Tue, Feb 9, 2010 at 10:05 PM, Richard Lemieux <rlemieu@cooptel.qc.ca> wrote:
> > > Andy,
> > >
> > > This is a great answer!  Thanks very much.  When I get into this situation
> > > again
> > > I will know what to look for.
> > >
> > > A possible reason why I got into this problem in the first place is that I
> > > tried
> > > many combinations of parameters with mplayer and azap in order to learn how
> > > to use the USB tuner in both the ATSC and the NTSC mode.  I will look back
> > > in the terminal history to see if I can find anything.
> > 
> > I think the key to figuring out the bug at this point is you finding a
> > sequence where you can reliably reproduce the oops.  If we have that,
> > then I can start giving you some code to try which we can see if it
> > addresses the problem.
> > 
> > For example, I would start by giving you a fix which results in us not
> > calling the firmware release if the request_firmware() call failed,
> > but it wouldn't be much help if you could not definitively tell me if
> > the problem is fixed.
> 
> 
> For the oops analysis here:
> 
> http://article.gmane.org/gmane.linux.drivers.video-input-infrastructure/15954
> 
> 
> I will also note that the file scope "fw_lock" mutex is rather
> inconsistently used in
> linux/drivers/base/fw_class.c:firmware_loading_store().  (I guess for
> not wanting to consume the timeout interval with sleeping?)
> 
> The mutex protects "case 1:", but all other cases appear to be only
> protected by atomic status bit checks that can fall through to
> fw_load_abort() which complete()'s the fw_priv->completion.
> 
> Also not that in the _request_firmware() this sequence is the only place
> a once good "fw_priv->fw" pointer is set to NULL:
> 
>         mutex_lock(&fw_lock);
>         if (!fw_priv->fw->size || test_bit(FW_STATUS_ABORT, &fw_priv->status)) {
>                 retval = -ENOENT;
>                 release_firmware(fw_priv->fw);
>                 *firmware_p = NULL;
>         }
>         fw_priv->fw = NULL;     <--------------- The only place it is set to NULL
>         mutex_unlock(&fw_lock);
> 
> 
> So if the timeout timer fires at nearly the same time as udev coming in
> and say "I'm done loading" without holding the mutex, one can run into
> the Ooops.  Not only that, I think the above code can leak memory under
> some circumstances when the "if" clause is not satisfied.
> 
> I think this really is a firmware_class.c issue.  I think the "just
> right" firmware loading timeouts and the particular computer system
> responsiveness, make this Ooops possible.  However, I'm amazed that a
> single person has tripped it more than once.
> 
> Revising the locking in linux/drivers/base/firmware_class.c should fix
> the problem.
> 
> I don't believe this comment in the code now:
> 
> /* fw_lock could be moved to 'struct firmware_priv' but since it is just
>  * guarding for corner cases a global lock should be OK */
> static DEFINE_MUTEX(fw_lock);
> 
> struct firmware_priv {
>         char *fw_id;
> 	...
> 
> And since "f_priv" is dynamically created and destroyed by
> request_firmware() I see no harm in 
> 
> 1. moving the mutex into struct firmware_priv
> 2. just always just grabbing an almost never contended mutex
> 3. getting rid of the file scope fw_lock.
> 
> except grabbing a mutex() while the timeout timer is running during
> loading, means one *could* sleep for a while consuming the timeout
> interval.

That sounds reasonable to me, care to make up a patch for this?

thanks,

greg k-h

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Andy Walls]

On Thu, 2010-02-11 at 20:11 -0800, Greg KH wrote:
> On Wed, Feb 10, 2010 at 10:34:56AM -0500, Andy Walls wrote:
> > On Tue, 2010-02-09 at 22:12 -0500, Devin Heitmueller wrote:
> > > On Tue, Feb 9, 2010 at 10:05 PM, Richard Lemieux <rlemieu@cooptel.qc.ca> wrote:
> > > > Andy,
> > > >
> > > > This is a great answer!  Thanks very much.  When I get into this situation
> > > > again
> > > > I will know what to look for.
> > > >
> > > > A possible reason why I got into this problem in the first place is that I
> > > > tried
> > > > many combinations of parameters with mplayer and azap in order to learn how
> > > > to use the USB tuner in both the ATSC and the NTSC mode.  I will look back
> > > > in the terminal history to see if I can find anything.
> > > 
> > > I think the key to figuring out the bug at this point is you finding a
> > > sequence where you can reliably reproduce the oops.  If we have that,
> > > then I can start giving you some code to try which we can see if it
> > > addresses the problem.
> > > 
> > > For example, I would start by giving you a fix which results in us not
> > > calling the firmware release if the request_firmware() call failed,
> > > but it wouldn't be much help if you could not definitively tell me if
> > > the problem is fixed.
> > 
> > 
> > For the oops analysis here:
> > 
> > http://article.gmane.org/gmane.linux.drivers.video-input-infrastructure/15954
> > 
> > 
> > I will also note that the file scope "fw_lock" mutex is rather
> > inconsistently used in
> > linux/drivers/base/fw_class.c:firmware_loading_store().  (I guess for
> > not wanting to consume the timeout interval with sleeping?)
> > 
> > The mutex protects "case 1:", but all other cases appear to be only
> > protected by atomic status bit checks that can fall through to
> > fw_load_abort() which complete()'s the fw_priv->completion.
> > 
> > Also not that in the _request_firmware() this sequence is the only place
> > a once good "fw_priv->fw" pointer is set to NULL:
> > 
> >         mutex_lock(&fw_lock);
> >         if (!fw_priv->fw->size || test_bit(FW_STATUS_ABORT, &fw_priv->status)) {
> >                 retval = -ENOENT;
> >                 release_firmware(fw_priv->fw);
> >                 *firmware_p = NULL;
> >         }
> >         fw_priv->fw = NULL;     <--------------- The only place it is set to NULL
> >         mutex_unlock(&fw_lock);
> > 
> > 
> > So if the timeout timer fires at nearly the same time as udev coming in
> > and say "I'm done loading" without holding the mutex, one can run into
> > the Ooops.  Not only that, I think the above code can leak memory under
> > some circumstances when the "if" clause is not satisfied.
> > 
> > I think this really is a firmware_class.c issue.  I think the "just
> > right" firmware loading timeouts and the particular computer system
> > responsiveness, make this Ooops possible.  However, I'm amazed that a
> > single person has tripped it more than once.
> > 
> > Revising the locking in linux/drivers/base/firmware_class.c should fix
> > the problem.
> > 
> > I don't believe this comment in the code now:
> > 
> > /* fw_lock could be moved to 'struct firmware_priv' but since it is just
> >  * guarding for corner cases a global lock should be OK */
> > static DEFINE_MUTEX(fw_lock);
> > 
> > struct firmware_priv {
> >         char *fw_id;
> > 	...
> > 
> > And since "f_priv" is dynamically created and destroyed by
> > request_firmware() I see no harm in 
> > 
> > 1. moving the mutex into struct firmware_priv
> > 2. just always just grabbing an almost never contended mutex
> > 3. getting rid of the file scope fw_lock.
> > 
> > except grabbing a mutex() while the timeout timer is running during
> > loading, means one *could* sleep for a while consuming the timeout
> > interval.
> 
> That sounds reasonable to me, care to make up a patch for this?

Yes.  But it will take me a while.  I don't have a git tree, because I
don't have high bandwidth internet yet.  (The cable company's been
delayed in laying cable to my home due to repeated snowstorms.)

I just didn't want the problem to fall through the cracks.  I'll submit
something to bugzilla for now.  If a user complains of this rare Ooops
when loading firmware, the current workaround is to lengthen the timeout
via sysfs.

Regards,
Andy

> thanks,
> 
> greg k-h

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Richard Lemieux]

Hi,

I was in the process of setting up my machine so I can run any of
the tests you might ask for.  First I needed a fully tested backup partition,
and then I needed to bring udev up to date.  But I see that the problem
is pretty much resolved right now.  As Devin said earlier I doubt I can ever
reproduce this event.  Thanks very much for everything you do for the Linux 
community.

Richard

Andy Walls wrote:
> Yes.  But it will take me a while.  I don't have a git tree, because I
> don't have high bandwidth internet yet.  (The cable company's been
> delayed in laying cable to my home due to repeated snowstorms.)
> 
> I just didn't want the problem to fall through the cracks.  I'll submit
> something to bugzilla for now.  If a user complains of this rare Ooops
> when loading firmware, the current workaround is to lengthen the timeout
> via sysfs.
> 
> Regards,
> Andy

Re: Driver crash on kernel 2.6.32.7. Interaction between cx8800 (DVB-S) and USB HVR Hauppauge 950q

[Devin Heitmueller]

On Tue, Feb 9, 2010 at 9:14 PM, Andy Walls <awalls@radix.net> wrote:
> Both Ooops below are related to userspace loading of firmware for the
> HVR-950Q.

Very strange.  The xc5000 function doesn't appear to really do
anything unusual.  It calls request_firmware(), pushes the code into
the chip, and then call release_firmware() [see
xc5000.c:xc5000_fwupload() ]

One thing that does jump out at me which could be problematic is the
function will call release_firmware() even if request_firmware()
fails.  I doubt that is the correct behavior.  And combined with the
fact that his dmesg shows the error "run_program:
'/lib/udev/firmware.sh' abnormal exit" makes me wonder if the
subsequent to release_firmware() despite the error condition is what
is causing the problem.

The other thing that is a bit unusual about the xc5000 in this
particular case is the time to load the firmware is exceptionally long
(around 7 seconds) due to a hardware bug in the au0828 which requires
us to run the i2c bus at a very slow rate.  Hence, it's possible that
the unusually long time between request_firmware() and
release_firmware() has exposed some sort of race in the firmware
loading core.

It would be useful if we could get the full dmesg output so we can get
some more context leading up to the oops.  Also, it would be helpful
if the user could enable the "debug=1" in the xc5000 modprobe options.

One more question: is the user doing any suspend/resume operations?
For example, is this a laptop in which he is closing the lid and this
is the first attempt to use the device after resume?

Devin


-- 
Devin J. Heitmueller - Kernel Labs
http://www.kernellabs.com